Lighthouse space usage - Increasing dramastically from 87GB to 430GB in 7 days

[luarx]

Description

We are running several Lighthouse clients and I have noticed that in 10% of them there are some ocassions were the volume usage is increased 5x in 7 days!

My temporal solution is about deleting the volume date and resync, after that the Lighthouse client is stable again. But some weeks later a different Lighthouse client repeats this weird behaviour...

Version

Lighthouse v4.1.0 (docker image)

Present Behaviour

The volume usage increases 5x in 7 days

Params:

          args: [
              "--debug-level=info",
              "--datadir=/beacondata",
              "--network=mainnet",
              "beacon_node",
              "--disable-enr-auto-update",
              "--enr-address=127.0.0.1",
              "--enr-tcp-port=9000",
              "--enr-udp-port=9000",
              "--port=9000" ,
              "--discovery-port=9000",
              "--eth1",
              "--http",
              "--http-address=0.0.0.0",
              "--http-port=5052",
              "--metrics",
              "--metrics-address=0.0.0.0",
              "--metrics-port=5054",
              "--listen-address=0.0.0.0",
              "--target-peers=100",
              "--http-allow-sync-stalled",
              "--disable-packet-filter",
              "--execution-endpoint=http://localhost:9545",
              "--jwt-secrets=/tmp/jwtsecret",
              "--disable-deposit-contract-sync",
              "--checkpoint-sync-url=https://beaconstate-mainnet.chainsafe.io"
              ]

Expected Behaviour

Do not increment so heavy the volume usage in a few days, at least some stable values

Steps to resolve

Do not increment so heavy the volume usage in a few days

[luarx]

Another screenshot of a different Ligthouse client that is using the same version and same params.
Look how the space was stable again after deleting the volume data and resyncing

[michaelsproul]

If you still have any oversized nodes (or if it happens again) you can try:

Running du -sh freezer_db chain_db in the $datadir/beacon. I suspect it's the chain_db that's bloated.

If it is, you can try running lighthouse db inspect --column ste --data /your/datadir to see if the beacon state storage is the culprit (I suspect it is).

We haven't identified the bug that causes this, but have had a few reports of it. The database schema is getting completely overhauled in a few versions time, with a new system that prunes states more aggressively and so far has not shown any signs of blowing up in the same way (see the tree states releases if you're curious).

Still, if we find the bug in the current DB it would be nice to fix it. Debug logs from an affected node would be helpful (DM me on Discord @sproul, or email me: michael at sigmaprime dot io)

[luarx]

Sure! I still have that node oversized to help to debug this issue

Here you are the results that you have asked for:

du -sh freezer_db chain_db
5.3G	freezer_db
432G	chain_db

I do not know if I am executing correctly this second one:

lighthouse db inspect --column ste --datadir beacondata/
Sep 22 14:08:26.602 INFO Running database manager for mainnet network
Fatal error: DBError { message: "Error { message: \"IO error: lock beacondata/beacon/freezer_db/LOCK: Resource temporarily unavailable\" }" }

Perfect, I will contact you in Discord

[michaelsproul]

Looks like you've got the command right but need to just stop the BN while you run it. It will produce quite a lot of output so you might also want to pipe it to a file

I'm afk from Discord for the weekend but will get in touch Monday :)

[michaelsproul]

Thanks, I can see what the issue is now:

• Your node stopped being able to delete finalized states from the database due to an error:

WARN Block pruning failed error: BeaconStateError(MissingBeaconBlock(SignedBeaconBlockHash(0x69eaa1973c1e57ae88d4d85d46c4a7e30684f0318cb3b3411a1339597aadbecf))), service: beacon

• Due to Lighthouse's current database schema, these states consume a lot of disk space (around 30GB/day).

The tree states release I mentioned should alleviate the latter point, because it results in vastly less data being stored on disk. However, it would be good to understand why the database is erroring, as I haven't seen this error before. Strangely the block that's missing from your DB isn't one that I can find: it's not part of the canonical chain and it wasn't seen by the couple of nodes I spot-checked (I'll check more thoroughly tomorrow).

It would be great if you could provide logs from around the time the database starting growing, as this might lead us to the mystery block and the root cause. For the best chance of success it would be great to have debug level logs, which should have been written by default to your datadir at /beacondata/beacon/logs/. If you could find the file that has Sept 15 (or whenever the issue started on this node) and DM that to me compressed, that would be great.

Thanks!

[luarx]

Good to know that! Thanks!

Unfortunately, I have only logs from September 20th because of the internal log rotation I would say...
Let me know if I can provide you some other info

[michaelsproul]

Any info logs from earlier that might have been retained by Docker or the OS?

[luarx]

I have checked and it is not possible neither, they have been rotated :(

[michaelsproul]

That's ok, thanks for your efforts! I'll see if I can dig up that block from somewhere and see if it provides a clue about what went wrong

[luarx]

In case that the same issue is present in some of my Lighthouse nodes, I will copy those logs before they are rotated @michaelsproul

[michaelsproul]

Hey @luarx I did some investigating and found a few interesting things:

• That block which was missing from your node (0x69eaa1973c1e57ae88d4d85d46c4a7e30684f0318cb3b3411a1339597aadbecf) was published at slot 7323584 building on a parent from 12 slots prior (!) at 7323572. The block graffiti was Avado and the proposer was 781777. The parent block has root 0xe6ae158ddfd054042b135fdf3691cc5b60f6b4bd2f01308911f77e72d2466ad3 which is the canonical block from that slot.
• The block was probably published by a Lighthouse validator (according to blockprint). This isn't a bad thing per se, as Lighthouse will publish blocks even when it's slightly out of sync in order to keep the network live. It can't always tell whether there are legitimately no blocks, or it's just out of sync.

Anyway, the details of the block's publishing probably aren't too important, because the issue is how it was processed by your node.

To get that error, the database pruning process must have hit the Ok(None) branch here:

lighthouse/beacon_node/beacon_chain/src/migrate.rs

Lines 487 to 496 in 441fc16

	for (head_hash, head_slot) in heads {
	// Load head block. If it fails with a decode error, it's likely a reverted block,
	// so delete it from the head tracker but leave it and its states in the database
	// This is suboptimal as it wastes disk space, but it's difficult to fix. A re-sync
	// can be used to reclaim the space.
	let head_state_root = match store.get_blinded_block(&head_hash) {
	Ok(Some(block)) => block.state_root(),
	Ok(None) => {
	return Err(BeaconStateError::MissingBeaconBlock(head_hash.into()).into())
	}

The pruning is trying to fetch a block which exists in the head_tracker from disk, which should always succeed if the head_tracker is in sync with what's on disk. The question then becomes:

How did we end up with a block in the head_tracker which isn't stored on disk?

There are only two places where we add a block to the head tracker. The main one is here, after importing the block:

lighthouse/beacon_node/beacon_chain/src/beacon_chain.rs

Lines 3105 to 3106 in 441fc16

	self.head_tracker
	.register_block(block_root, parent_root, slot);

Notably this happens after the block is written to disk, here:

lighthouse/beacon_node/beacon_chain/src/beacon_chain.rs

Lines 3024 to 3028 in 441fc16

	ops.push(StoreOp::PutBlock(block_root, signed_block.clone()));
	ops.push(StoreOp::PutState(block.state_root(), &state));
	let txn_lock = self.store.hot_db.begin_rw_transaction();
	if let Err(e) = self.store.do_atomically(ops) {

So on this code path it seems like it would be impossible to end up in a situation where the block is in the head tracker, but not written to disk. Even if the node crashed or was SIGKILLed in between those two calls, the result would be that the block was on disk and not in the head tracker.

So where's the other place we call register_block? Here, on node startup when reverting a missed hard fork:

lighthouse/beacon_node/beacon_chain/src/builder.rs

Lines 680 to 697 in 441fc16

	error!(
	log,
	"Error decoding head block";
	"message" => "This node has likely missed a hard fork. \
	It will try to revert the invalid blocks and keep running, \
	but any stray blocks and states will not be deleted. \
	Long-term you should consider re-syncing this node."
	);
	let (block_root, block) = revert_to_fork_boundary(
	current_slot,
	initial_head_block_root,
	store.clone(),
	&self.spec,
	&log,
	)?;
	// Update head tracker.
	head_tracker.register_block(block_root, block.parent_root(), block.slot());

I doubt that your node could have hit this, because it hadn't missed the most recent fork (Capella, which happened back in April). It could have tried to run that revert if the head block was corrupt on disk, but even if it did, it wouldn't have selected 7323584 because of the condition here:

lighthouse/beacon_node/beacon_chain/src/fork_revert.rs

Lines 57 to 58 in 441fc16

	if block.slot() < fork_epoch.start_slot(E::slots_per_epoch()) {
	Some((block_root, block))

So, in terms of entries being added to the head tracker without the block existing on disk, I think we're in the clear.

The other option is that a block was deleted from disk, but not deleted from the head_tracker. There's only one place where we delete from the head tracker, so lets look for a race there:

lighthouse/beacon_node/beacon_chain/src/migrate.rs

Lines 629 to 631 in 441fc16

	for head_hash in abandoned_heads {
	head_tracker_lock.remove(&head_hash);
	}

Those head tracker deletions get added to an atomic I/O batch here, together with the block deletions:

lighthouse/beacon_node/beacon_chain/src/migrate.rs

Lines 651 to 659 in 441fc16

	// Persist the head in case the process is killed or crashes here. This prevents
	// the head tracker reverting after our mutation above.
	let persisted_head = PersistedBeaconChain {
	_canonical_head_block_root: DUMMY_CANONICAL_HEAD_BLOCK_ROOT,
	genesis_block_root,
	ssz_head_tracker: SszHeadTracker::from_map(&head_tracker_lock),
	};
	drop(head_tracker_lock);
	kv_batch.push(persisted_head.as_kv_store_op(BEACON_CHAIN_DB_KEY));

If LevelDB (and the filesystem) uphold their ACID guarantees, then this batch should happen atomically: either the blocks & head tracker entries are both deleted, or neither are. Even though we release the lock on the head tracker early (drop(head_tracker)), the worst that can happen is that another thread writes the updated tracker to disk before the blocks are deleted, leading to the block not appearing in the head tracker while still existing on disk (this is safe, we're looking for the opposite: block in head tracker but not on disk).

The other possibility is that blocks are deleted elsewhere, but this is not the case. The only usage of StoreOp::DeleteBlock is in the migrator/pruner, and the delete_block function is not used outside of tests.

Therefore, I'm a bit stumped. For the bug to occur, one of the assumptions I've made must have been violated, e.g.

• LevelDB is not able to do atomic I/O on your disk due to a filesystem issue. I think this is possible if you're using an NFS drive, as NFS drives don't generally provide strong atomicity guarantees. It does look like you're using Docker and/or Kubernetes, so it would be interesting to know if you're using an NFS mount for the datadir.
• LevelDB isn't able to do atomic I/O properly due to us not calling fsync. We call fsync every so often, but not after every write batch. My understanding on LevelDB's guarantees is that it should still uphold atomicity of batches in this case, but I could be wrong. I think the NFS explanation is more likely.
• The hardware (e.g RAM/disk) is faulty (probably not, as you've seen it on multiple machines).

Even if we don't understand exactly how it happened, we could still try to mitigate the impact of this occurring by making the pruning process ignore this kind of error. We could simply log a warning whenever this is detected, rather than stalling pruning indefinitely (which is what leads to the database growth). The outcome would be a little bit of database bloat, due to states/blocks that weren't fully cleaned up, but I think it would be better than the alternative. I think this is probably a good harm-minimisation approach, particularly if we discover that this is quite likely on NFS.

Long-term we could also mitigate it by:

• Being more aggressive with calling fsync (if the fsync hunch turns out to be correct)
• Using a different backend from LevelDB to see if suffers the same issues (this is in-progress here: Modularize beacon node backend #4718).

---

TL;DR: I haven't been able to find an obvious Lighthouse bug, and suspect foul play from the filesystem, possibly NFS.

[luarx]

Amazing, that you for time debugging this and sharing what you have found in such a detailed explanation! 🙌 🙌 🙌

• About the filesystem
  • We use AWS EBS volumes, so they are not NFS, because NFS presents a file-based interface while EBS is a block/device-based interface
• About The hardware (e.g RAM/disk) is faulty (probably not, as you've seen it on multiple machines).
  • That's right, it had happened on multiple and different machines

Unfortunately I can not support more on this as it is internal Lighthouse logic that it escapes my control... but I do agree that a good solution at least is to make the pruning process ignore this kind of error to prevent the volume usage increase 👀

[luarx]

Some more information in case that it can be useful:

• We are running Lighthouse v4.1.0 from May (previously we had v4.0.1) for mainnet nodes
• During the last 12 months, we saw the first volume usage spike in July 12, 23h UTC (attached image)
  
• We run Lighthouse nodes for mainnet and gnosis-chain networks, and only mainnet nodes had problems.
  • It is true that Gnosis-chain nodes run v4.1.0 from May, then were upgraded to v4.2.0 on Jun 26, later to v4.3.0 in July 17 and finally in September 20 to v4.4.1
• In September, we saw 2 usage spikes in 2 different nodes running 2 different execution nodes and in 2 different machines. Almost the same day, one was in September 13 and the other September 14