bug: history.transactions flag not honored during resync (keeping ancients)

[ryanschneider]

System information

Geth version: 1.13.5
CL client & version: teku v23.11.0
OS & Version: Linux

Expected behaviour

After using geth removedb (and choosing n on deleting ancients) and restarting, the node should resync and honor the value of --history.transactions 0.

Actual behaviour

After using geth removedb (and choosing n on deleting ancients) and restarting, the node resyncs but seems to only index "recent" transactions.

Steps to reproduce the behaviour

• Sync a node to head (I've tested reproduced on both 1.13.5 and 1.13.1 using both leveldb and pebble/PBSS)
  • relevant arguments:

/usr/bin/geth --mainnet --syncmode full --db.engine=leveldb --history.transactions 0 --snapshot=true --datadir /mnt/local/ethereum

• Stop the node
• Run geth removedb
• Choose y for deleting full node state, n for ancients as shown below:

$ sudo -u geth geth removedb --db.engine=leveldb --datadir /mnt/local/ethereum
INFO [12-12|00:26:24.953] Maximum peer count                       ETH=50 LES=0 total=50
INFO [12-12|00:26:24.955] Smartcard socket not found, disabling    err="stat /run/pcscd/pcscd.comm: no such file or directory"
INFO [12-12|00:26:24.956] Using leveldb as db engine
INFO [12-12|00:26:24.958] Global gas cap set to 10x block gas limit
INFO [12-12|00:26:24.959] Initializing the KZG library             backend=gokzg
Remove full node state database (/mnt/local/ethereum/geth/chaindata)? [y/n] y
Remove full node state database (/mnt/local/ethereum/geth/chaindata)? [y/n] y
INFO [12-12|00:26:57.218] Database successfully deleted            path=/mnt/local/ethereum/geth/chaindata elapsed=26.749s
Remove full node ancient database (/mnt/local/ethereum/geth/chaindata/ancient)? [y/n] n
Remove full node ancient database (/mnt/local/ethereum/geth/chaindata/ancient)? [y/n] n
INFO [12-12|00:27:06.826] Database deletion skipped                path=/mnt/local/ethereum/geth/chaindata/ancient
INFO [12-12|00:27:06.827] Light node database missing              path=/mnt/local/ethereum/geth/lightchaindata

• Restart the node
• Wait "overnight" while node resyncs
• Eventually Node is synced to head
• Try retrieving an older tx, e.g.: https://etherscan.io/tx/0xa243c78518ea5b6ebdccb61f54f3f87f44e84b7c028560386196e6bc77de37dd

$ sudo geth attach /mnt/local/ethereum/geth.ipc
Welcome to the Geth JavaScript console!

instance: Geth/v1.13.5-omnibus-62a11504/linux-amd64/go1.21.4
at block: 18771040 (Tue Dec 12 2023 15:36:59 GMT+0000 (UTC))
 datadir: /mnt/local/ethereum
 modules: admin:1.0 debug:1.0 engine:1.0 eth:1.0 miner:1.0 net:1.0 rpc:1.0 txpool:1.0 web3:1.0

To exit, press ctrl-d or type exit
> eth.getTransaction("0xa243c78518ea5b6ebdccb61f54f3f87f44e84b7c028560386196e6bc77de37dd")
null

Furthermore, I scanned the logs for Indexing transactions and never had any hits, so as far as I can tell rawdb.indexTransactions never runs.

I'm trying again now w/o using the ancients, and it seems to be working, but I won't know for certain until it fully syncs again.

[rjl493456442]

Are you sure your node is synced?

You are running full sync on mainnet and it can take roughly 2 weeks. You are retrieving a transaction in block 16164065, my gut feeling is this transaction is not indexed yet.

[ryanschneider]

Oops sorry the node was using snap sync, I copied the sync mode from the wrong server. The machine was definitely synced to head and passing all our health checks.

…

On Wed, Dec 13, 2023 at 7:48 PM rjl493456442 ***@***.***> wrote: Are you sure your node is synced? You are running full sync on mainnet and it can take roughly 2 weeks. You are retrieving a transaction in block 16164065 <https://etherscan.io/block/16164065>, my gut feeling is this transaction is not indexed yet. — Reply to this email directly, view it on GitHub <#28673 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAANCEATWD37LYF7SFERQRDYJJZKHAVCNFSM6AAAAABASAOMEWVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTQNJVGA4DIMBVGI> . You are receiving this because you authored the thread.Message ID: ***@***.***>

[rjl493456442]

Can you provide the command for relaunching geth node?

[ryanschneider]

/usr/bin/geth --mainnet --syncmode snap --db.engine=leveldb  --pprof --cache 4096 --cache.blocklogs 1024 --rpc.gascap 500000000 --rpc.txfeecap 0 --history.transactions 0 --rpc.allow-unprotected-txs --snapshot=true --datadir /mnt/local/ethereum

(I removed a bunch of unrelated --http --txpool and --ws arguments for clarity)

I did confirm that the txs are indexed correctly with the above arguments if I fully delete the ancients, even though interestingly I never see the log line containing Indexing transactions.

I'll try reproducing on holesky or sepolia or somewhere faster to iterate on, but I think what's happening is that when the ancients already exist they are reused but rawdb.WriteTxLookupEntriesByBlock(..) is never called, I see it called in directly in writeAncients and indirectly in indexTransactions but I don't think it's called in the routine that "reimports" the ancients when the state db is blown away but the ancients db is kept.

[ryanschneider]

Ok, I have a clean reproduction, I ended up stick w/ mainnet so it took a bit longer.

• Node synced to head and confirmed healthy on all fronts.
• Node was shutdown, then geth removedb --datadir /mnt/local/ethereum (choosing y for state and n for ancients)
• Confirmed that the only contents of /mnt/local/ethereum/geth/chaindata was a ~600GB /mnt/local/ethereum/geth/chaindata/ancient directory.
• Node was restarted w/ these arguments:

/usr/bin/geth --mainnet --syncmode snap --db.engine=leveldb  --pprof --cache 4096 --cache.blocklogs 1024 --rpc.gascap 500000000 --rpc.txfeecap 0 --txlookuplimit 0 --rpc.allow-unprotected-txs --snapshot=true --datadir /mnt/local/ethereum --authrpc.jwtsecret /mnt/local/ethereum/engine-jwt.key

• Confirmed that DB was reinitialized by the freezer and then snap sync was started:

Dec 15 00:50:51 ip-10-0-68-166 geth[14941]: INFO [12-15|00:50:51.551] Initializing database from freezer       total=18,697,685 number=400,000 hash=1e77d8..38ba14 elapsed=1.014s
Dec 15 00:50:54 ip-10-0-68-166 systemd[1]: Started Geth.
Dec 15 00:50:59 ip-10-0-68-166 geth[14941]: INFO [12-15|00:50:59.822] Initializing database from freezer       total=18,697,685 number=2,300,000 hash=a71398..42f9fd elapsed=9.286s
Dec 15 00:51:08 ip-10-0-68-166 geth[14941]: INFO [12-15|00:51:08.250] Initializing database from freezer       total=18,697,685 number=3,900,000 hash=cfe6ce..495e75 elapsed=17.714s
Dec 15 00:51:16 ip-10-0-68-166 geth[14941]: INFO [12-15|00:51:16.822] Initializing database from freezer       total=18,697,685 number=5,400,000 hash=9c7aa1..e4791a elapsed=26.286s
Dec 15 00:51:25 ip-10-0-68-166 geth[14941]: INFO [12-15|00:51:25.084] Initializing database from freezer       total=18,697,685 number=6,700,000 hash=c8b204..2054e6 elapsed=34.548s
Dec 15 00:51:33 ip-10-0-68-166 geth[14941]: INFO [12-15|00:51:33.102] Initializing database from freezer       total=18,697,685 number=7,900,000 hash=a33485..67a32b elapsed=42.565s
Dec 15 00:51:41 ip-10-0-68-166 geth[14941]: INFO [12-15|00:51:41.525] Initializing database from freezer       total=18,697,685 number=9,200,000 hash=e21d53..d6fcc8 elapsed=50.989s
Dec 15 00:51:50 ip-10-0-68-166 geth[14941]: INFO [12-15|00:51:50.041] Initializing database from freezer       total=18,697,685 number=10,700,000 hash=0b96ac..31a4f0 elapsed=59.505s
Dec 15 00:51:58 ip-10-0-68-166 geth[14941]: INFO [12-15|00:51:58.248] Initializing database from freezer       total=18,697,685 number=12,800,000 hash=bc1378..af7735 elapsed=1m7.712s
Dec 15 00:52:06 ip-10-0-68-166 geth[14941]: INFO [12-15|00:52:06.361] Initializing database from freezer       total=18,697,685 number=14,500,000 hash=e31116..7c416a elapsed=1m15.825s
Dec 15 00:52:14 ip-10-0-68-166 geth[14941]: INFO [12-15|00:52:14.543] Initializing database from freezer       total=18,697,685 number=16,000,000 hash=6f377d..c6bb16 elapsed=1m24.007s
Dec 15 00:52:22 ip-10-0-68-166 geth[14941]: INFO [12-15|00:52:22.992] Initializing database from freezer       total=18,697,685 number=17,500,000 hash=bee1c9..3ab51c elapsed=1m32.455s
Dec 15 00:52:30 ip-10-0-68-166 geth[14941]: INFO [12-15|00:52:30.233] Initialized database from freezer        blocks=18,697,685 elapsed=1m39.697s
Dec 15 00:52:30 ip-10-0-68-166 geth[14941]: INFO [12-15|00:52:30.248] Loaded most recent local header          number=18,697,684 hash=17ebeb..03313f td=58,750,003,716,598,352,816,469 age=1w5d15h
Dec 15 00:52:30 ip-10-0-68-166 geth[14941]: INFO [12-15|00:52:30.248] Loaded most recent local block           number=0          hash=d4e567..cb8fa3 td=17,179,869,184                 age=54y8mo3w
Dec 15 00:52:30 ip-10-0-68-166 geth[14941]: INFO [12-15|00:52:30.248] Loaded most recent local snap block      number=18,697,684 hash=17ebeb..03313f td=58,750,003,716,598,352,816,469 age=1w5d15h
Dec 15 00:52:30 ip-10-0-68-166 geth[14941]: WARN [12-15|00:52:30.248] Failed to load snapshot                  err="missing or corrupted snapshot"
Dec 15 00:52:30 ip-10-0-68-166 geth[14941]: INFO [12-15|00:52:30.248] Rebuilding state snapshot
Dec 15 00:52:30 ip-10-0-68-166 geth[14941]: INFO [12-15|00:52:30.249] Resuming state snapshot generation       root=d7f897..0f0544 accounts=0 slots=0 storage=0.00B dangling=0 elapsed="361.921µs"
Dec 15 00:52:30 ip-10-0-68-166 geth[14941]: INFO [12-15|00:52:30.249] Upgrading chain index                    type=bloombits percentage=0
Dec 15 00:52:30 ip-10-0-68-166 geth[14941]: INFO [12-15|00:52:30.249] Initialized transaction indexer          limit=0
Dec 15 00:52:30 ip-10-0-68-166 geth[14941]: INFO [12-15|00:52:30.258] Enabled snap sync                        head=0 hash=d4e567..cb8fa3

• About 9h later state was downloaded and state healing began:

Dec 15 09:17:55 ip-10-0-68-166 geth[14941]: INFO [12-15|09:17:55.005] Syncing: state download in progress      synced=99.98%  state=275.44GiB accounts=233,508,198@53.04GiB slots=1,071,866,568@21>
Dec 15 09:17:59 ip-10-0-68-166 geth[14941]: INFO [12-15|09:17:59.232] Syncing: state download in progress      synced=100.00% state=275.46GiB accounts=233,549,717@53.05GiB slots=1,071,915,553@21>
Dec 15 09:18:01 ip-10-0-68-166 geth[14941]: INFO [12-15|09:18:01.362] Forkchoice requested sync to new head    number=18,790,575 hash=8d36ad..9827b7 finalized=unknown
Dec 15 09:18:02 ip-10-0-68-166 geth[14941]: INFO [12-15|09:18:02.669] Syncing: chain download in progress      synced=100.00% chain=628.35GiB headers=18,790,575@8.62GiB bodies=18,790,495@450.57G>
Dec 15 09:18:07 ip-10-0-68-166 geth[14941]: INFO [12-15|09:18:07.232] Syncing: state healing in progress       accounts=1077@58.13KiB        slots=362@27.87KiB            codes=2@15.26KiB

• After about 12m of healing the snapshot generation began:

Dec 15 09:30:19 ip-10-0-68-166 geth[14941]: INFO [12-15|09:30:19.831] Syncing: state healing in progress       accounts=141,330@7.52MiB      slots=224,370@17.01MiB        codes=143@963.27KiB    >
Dec 15 09:30:19 ip-10-0-68-166 geth[14941]: INFO [12-15|09:30:19.838] Rebuilding state snapshot
Dec 15 09:30:19 ip-10-0-68-166 geth[14941]: INFO [12-15|09:30:19.839] Committed new head block                 number=18,790,553 hash=c0a786..5035f6
Dec 15 09:30:19 ip-10-0-68-166 geth[14941]: INFO [12-15|09:30:19.840] Resuming state snapshot generation       root=958dc2..2e1f8d accounts=0                    slots=0                       sto>
Dec 15 09:30:24 ip-10-0-68-166 geth[14941]: INFO [12-15|09:30:24.147] Aborting state snapshot generation       root=958dc2..2e1f8d in=00136c..b383b6 at=b3d790..ef76f8 accounts=67552             >
Dec 15 09:30:24 ip-10-0-68-166 geth[14941]: INFO [12-15|09:30:24.147] Resuming state snapshot generation       root=206cb1..f5cff8 in=00136c..b383b6 at=b3d790..ef76f8 accounts=67552

• 4.5h or so later state generation completed:

Dec 15 14:05:56 ip-10-0-68-166 geth[14941]: INFO [12-15|14:05:56.266] Generating state snapshot                root=18b9c5..3990ca in=ffeb92..4e53dc at=77c257..647c7b accounts=228,095,011       >
Dec 15 14:06:02 ip-10-0-68-166 geth[14941]: INFO [12-15|14:06:02.853] Generated state snapshot                 accounts=228,166,328          slots=1,088,101,530           storage=88.79GiB   dang>
Dec 15 14:06:12 ip-10-0-68-166 geth[14941]: INFO [12-15|14:06:12.458] Imported new potential chain segment     number=18,792,002 hash=c22b63..7c6a62 blocks=1          txs=385  mgas=23.005  elaps>

• And the node has been in a steady state of importing new head blocks as they come ever since:

Dec 15 18:14:23 ip-10-0-68-166 geth[14941]: INFO [12-15|18:14:23.799] Chain head was updated                   number=18,793,230 hash=3dda92..c05bde root=ad252a..1da984 elapsed=2.754502ms
Dec 15 18:14:36 ip-10-0-68-166 geth[14941]: INFO [12-15|18:14:36.903] Imported new potential chain segment     number=18,793,231 hash=4f46ea..335c05 blocks=1          txs=227  mgas=19.133  elaps>

However, older transactions are not available, e.g. this one from block 500002: https://etherscan.io/tx/0x45215aa0da9b7597d233d96b6f7c4ac311edaba77a99ecc6471c59663554914f

> eth.getTransaction("0x45215aa0da9b7597d233d96b6f7c4ac311edaba77a99ecc6471c59663554914f")
null

• Going back to the initial logs, we saw:

Dec 15 00:52:30 ip-10-0-68-166 geth[14941]: INFO [12-15|00:52:30.248] Loaded most recent local header          number=18,697,684 hash=17ebeb..03313f td=58,750,003,716,598,352,816,469 age=1w5d15h
Dec 15 00:52:30 ip-10-0-68-166 geth[14941]: INFO [12-15|00:52:30.248] Loaded most recent local block           number=0          hash=d4e567..cb8fa3 td=17,179,869,184                 age=54y8mo3w
Dec 15 00:52:30 ip-10-0-68-166 geth[14941]: INFO [12-15|00:52:30.248] Loaded most recent local snap block      number=18,697,684 hash=17ebeb..03313f td=58,750,003,716,598,352,816,469 age=1w5d15h

• So, I'm curious if block 18,697,684 ends up being the cutoff for what is and isn't indexed. This is the first tx in block 18697684: https://etherscan.io/tx/0x306c2c4b43a5628a2f9118cef14dea22a587de9fc12660b323e174b702039f86

• And sure enough:

> eth.getTransaction("0x306c2c4b43a5628a2f9118cef14dea22a587de9fc12660b323e174b702039f86")
null

• So let's try a tx in block 18697685: https://etherscan.io/tx/0x61871bd101372d11e1d3f5c427fb4327db3472cbed19931b774f56c50431162f

> eth.getTransaction("0x61871bd101372d11e1d3f5c427fb4327db3472cbed19931b774f56c50431162f")
{
  accessList: [],
  blockHash: "0xac41987349c41061d557b0c98063c0bd61979a3aa34a34bdd76ea0e3ef359965",
  blockNumber: 18697685,
  chainId: "0x1",
  from: "0x5741d02852bfb7a05416a4ef412968ec2b88fcae",
  gas: 21000,
  gasPrice: 47132796261,
  hash: "0x61871bd101372d11e1d3f5c427fb4327db3472cbed19931b774f56c50431162f",
  input: "0x",
  maxFeePerGas: 48000000000,
  maxPriorityFeePerGas: 40000000,
  nonce: 9,
  r: "0x384caf10d5a27756f41745ac03446ea2451577f14ccb2ec099dd59ff1208d8fc",
  s: "0x6dfede1dd40787658cc930235b48fa10d32cfcfc4298aeb511e2972c310328d3",
  to: "0xf52605c7b778563a5a9144ef4dc53b57463ca2c7",
  transactionIndex: 210,
  type: "0x2",
  v: "0x0",
  value: 25015950000000000,
  yParity: "0x0"
}

I think this makes it pretty evident that something is going wrong w/ the freezer tx indexing logic. I looked at the code, and couldn't find anything obvious, but here's the code I followed:

• First off, when resyncing from ancients, InitDatabaseFromFreezer is called from NewBlockChain here: https://github.com/ethereum/go-ethereum/blob/master/core/blockchain.go#L330-L335
• This in turn calls WriteHeadHeaderHash
• Later in NewBlockChain we call maintainTxIndex here: https://github.com/ethereum/go-ethereum/blob/master/core/blockchain.go#L471

So, now we are in maintainTxIndex in another go routine, and the log.Info at it's start is called:

Dec 15 00:52:30 ip-10-0-68-166 geth[14941]: INFO [12-15|00:52:30.249] Initialized transaction indexer          limit=0

• maintainTxIndex should be spawning a indexBlocks routine to index the txs, but I never see Indexing transactions in the logs.
• nor do any indexingBlocks goroutines show up in pprof goroutine lists on http://localhost:6060/debug/pprof/goroutine?debug=1, but maintainTxIndex does:

1 @ 0x452fce 0x463525 0xd5186d 0x4866a1
#	0xd5186c	github.com/ethereum/go-ethereum/core.(*BlockChain).maintainTxIndex+0x36c	github.com/ethereum/go-ethereum/core/blockchain.go:2504

Also note that:

> debug.dbGet("TransactionIndexTail")
"0x0000000000000000"

So rawdb.ReadTxIndexTail should return 0 (I also checked this value while the snap sync was ongoing and it was 0 then as well, so something called WriteTxIndexTail(0) pretty early on in the process.

[rjl493456442]

Thanks for the information, I will debug it tomorrow.

[rjl493456442]

@ryanschneider can you try this branch #28703?

[ryanschneider]

@rjl493456442 ya I'll give it a shot. Would I expect it to start indexing these txs as soon as I upgrade the node already in a bad state to this branch, or do I need to upgrade and then repeat the steps above to resync from ancients?

[ryanschneider]

I upgraded my node to your branch, and can confirm the new error message:

> eth.getTransaction("0x306c2c4b43a5628a2f9118cef14dea22a587de9fc12660b323e174b702039f86")
Error: tx is not existent or not indexed, index-tail: 0, index-head: 18829693, limit: entire chain
	at web3.js:6365:9(39)
	at send (web3.js:5099:62(29))
	at <eval>:1:19(3)

But this also confirms the branch doesn't detect and repair the issue after the fact. I'll wait until I hear from you before I wipe and resync in case we want to try changes that would also repair the issue.

[rjl493456442]

But this also confirms the branch doesn't detect and repair the issue after the fact

This branch won't fix the issue you have right now. It just avoids the issue to happen again.

If you want to fix your node, it's pretty simple

• Restart your node and set the history.transactions to 1, it will unindex the entire chain but only keep the indexes of latest block. You have to wait maybe 1 or 2 hours to let it finish the job
• Restart your node and set the history.transactions to 0, it will reindex the entire chain

[ryanschneider]

This is just a throw-away node so I'll skip straight to re-syncing w/ the branched version, but good to know how to reindex if needed in the future, thanks!

Resync has started after another geth removedb --datadir /mnt/local/ethereum (w/ y and n and confirmation that the ancients were the only files left):

Dec 21 18:53:10 ip-10-0-68-166 geth[1286553]: INFO [12-21|18:53:10.356] Initializing database from freezer       total=18,746,138 number=500,000 hash=794a1b..300d84 elapsed=1.318s
...
Dec 21 18:54:46 ip-10-0-68-166 geth[1286553]: INFO [12-21|18:54:46.601] Initialized database from freezer        blocks=18,746,138 elapsed=1m37.563s
Dec 21 18:54:46 ip-10-0-68-166 geth[1286553]: INFO [12-21|18:54:46.616] Loaded most recent local header          number=18,746,137 hash=afc001..3c5323 td=58,750,003,716>
Dec 21 18:54:46 ip-10-0-68-166 geth[1286553]: INFO [12-21|18:54:46.616] Loaded most recent local block           number=0          hash=d4e567..cb8fa3 td=17,179,869,184>
Dec 21 18:54:46 ip-10-0-68-166 geth[1286553]: INFO [12-21|18:54:46.616] Loaded most recent local snap block      number=18,746,137 hash=afc001..3c5323 td=58,750,003,716>
Dec 21 18:54:46 ip-10-0-68-166 geth[1286553]: WARN [12-21|18:54:46.616] Failed to load snapshot                  err="missing or corrupted snapshot"
Dec 21 18:54:46 ip-10-0-68-166 geth[1286553]: INFO [12-21|18:54:46.616] Rebuilding state snapshot

[ryanschneider]

I also confirmed that while syncing the txs aren't indexed (as expected) and the index head/tail are both 0:

> eth.getTransaction("0x306c2c4b43a5628a2f9118cef14dea22a587de9fc12660b323e174b702039f86")
Error: tx is not existent or not indexed, index-tail: 0, index-head: 0, limit: entire chain
	at web3.js:6365:9(39)
	at send (web3.js:5099:62(29))
	at <eval>:1:19(3)