Cardano-node: [BUG] - ImmutableDB incorrectly used

[gufmar]

External

Summary
I upgraded a core node on testnet to 1.21.1
3h after the restart and having produced blocks the node crashed...

ApiMisuse (InvalidIteratorRangeError (StreamFromExclusive (At (Block {blockPointSlot = SlotNo 7608971, blockPointHash = efc66f4128529e380f3541c71928fcc8ad9e8415a67419c46941f8a7cba7cc40}))) (StreamToInclusive (RealPoint (SlotNo 1389855) 7234ec3677da8cac4ee8c65c53a3eb220d116daa87403541ceba3f7b47d66300))) CallStack (from HasCallStack):
  prettyCallStack, called at src/Ouroboros/Consensus/Storage/ImmutableDB/API.hs:350:41 in ouroboros-consensus-0.1.0.0-inplace:Ouroboros.Consensus.Storage.ImmutableDB.API
  throwApiMisuse, called at src/Ouroboros/Consensus/Storage/ImmutableDB/Impl/Iterator.hs:129:16 in ouroboros-consensus-0.1.0.0-inplace:Ouroboros.Consensus.Storage.ImmutableDB.Impl.Iterator
  streamImpl, called at src/Ouroboros/Consensus/Storage/ImmutableDB/Impl.hs:271:34 in ouroboros-consensus-0.1.0.0-inplace:Ouroboros.Consensus.Storage.ImmutableDB.Impl
  stream_, called at src/Ouroboros/Consensus/Storage/ImmutableDB/API.hs:160:7 in ouroboros-consensus-0.1.0.0-inplace:Ouroboros.Consensus.Storage.ImmutableDB.API
  stream, called at src/Ouroboros/Consensus/Storage/ImmutableDB/API.hs:517:19 in ouroboros-consensus-0.1.0.0-inplace:Ouroboros.Consensus.Storage.ImmutableDB.API
  streamAfterPoint, called at src/Ouroboros/Consensus/Storage/ChainDB/Impl/LgrDB.hs:444:11 in ouroboros-consensus-0.1.0.0-inplace:Ouroboros.Consensus.Storage.ChainDB.Impl.LgrDB
  streamAfter, called at src/Ouroboros/Consensus/Storage/ChainDB/Impl/LgrDB.hs:436:35 in ouroboros-consensus-0.1.0.0-inplace:Ouroboros.Consensus.Storage.ChainDB.Impl.LgrDB
  streamAfter, called at src/Ouroboros/Consensus/Storage/LedgerDB/OnDisk.hs:122:5 in ouroboros-consensus-0.1.0.0-inplace:Ouroboros.Consensus.Storage.LedgerDB.OnDisk
  streamAll, called at src/Ouroboros/Consensus/Storage/LedgerDB/OnDisk.hs:295:5 in ouroboros-consensus-0.1.0.0-inplace:Ouroboros.Consensus.Storage.LedgerDB.OnDisk
  initStartingWith, called at src/Ouroboros/Consensus/Storage/LedgerDB/OnDisk.hs:278:27 in ouroboros-consensus-0.1.0.0-inplace:Ouroboros.Consensus.Storage.LedgerDB.OnDisk
  initFromSnapshot, called at src/Ouroboros/Consensus/Storage/LedgerDB/OnDisk.hs:222:28 in ouroboros-consensus-0.1.0.0-inplace:Ouroboros.Consensus.Storage.LedgerDB.OnDisk
  initLedgerDB, called at src/Ouroboros/Consensus/Storage/ChainDB/Impl/LgrDB.hs:234:7 in ouroboros-consensus-0.1.0.0-inplace:Ouroboros.Consensus.Storage.ChainDB.Impl.LgrDB
  initFromDisk, called at src/Ouroboros/Consensus/Storage/ChainDB/Impl/LgrDB.hs:202:23 in ouroboros-consensus-0.1.0.0-inplace:Ouroboros.Consensus.Storage.ChainDB.Impl.LgrDB
  openDB, called at src/Ouroboros/Consensus/Storage/ChainDB/Impl.hs:129:26 in ouroboros-consensus-0.1.0.0-inplace:Ouroboros.Consensus.Storage.ChainDB.Impl

cardano-node: ImmutableDB incorrectly used, indicative of a bug

I had to stop another node, rsync the db folder and restart both nodes

System info:

• OS: Ubuntu
• Version 20.04
• Node version 1.21.1

[mrBliss]

This is a known bug. I only expect you to run into it after fiddling with the database folder, e.g., copying snapshots to <db>/ledger or deleting files from <db>/immutable.

This bug has been fixed, but that fix unfortunately didn't make it into the release. It will be in the next one.

In the meantime, there is a workaround: in the trace message there will be mention of a disk snapshot that is being read. If you delete the file with that name (just a number) from the <db>/ledger folder, you should be good to go. Unless you encounter the same error again, in which case you'll have to delete the other snapshot mentioned. After this, a full ledger rebuild might be necessary.

[rphair]

We built our DB from a snapshot of <db>/ledger, like probably most others when upgrading to 1.20.0, so unless told otherwise I would assume that we (and many others) should expect to run into this bug if we upgrade to 1.21.1 without taking the above workaround... which isn't yet detailed enough for us to follow.

So we've decided not to upgrade our stake pool servers (currently all on 1.20.0) because we're in a dilemma: we have some massively larger delegation epochs coming up in 3+ days and cannot afford any unanticipated downtime. We don't want poor performance on our node, if we do face that from our older version, but can't rely on this fix being included in a newer release in the next 3 days before the next epoch.

If anyone has more info that would help us & other SPOs decide on whether to upgrade to 1.21.1 (re: the release schedule beyond that version, the workaround posted above, or the acceptability of going forward with 1.20.0 for the next 3 or 4 epochs), please let us know.

[mrBliss]

We built our DB from a snapshot of <db>/ledger, like probably most others when upgrading to 1.20.0, so unless told otherwise I would assume that we (and many others) should expect to run into this bug if we upgrade to 1.21.1 without taking the above workaround... which isn't yet detailed enough for us to follow.

To be clear, no ledger rebuild is needed for the upgrade from 1.20 to 1.21.0/1. Only when upgrading from a version < 1.20 to a version >= 1.20. So an upgrade from 1.20.0 to 1.21.1 should go smoothly. No need to rebuild and thus no need to fiddle with the database folder like for the previous upgrade. I believe users are running into this bug exactly because they're unnecessarily fiddling with the database and getting it wrong.

It's very easy to check whether your database is in a correct state, just spin up a non-block producing node pointed at that database folder (not while another node is still using it as a database, of course). If it starts instantly, you got it right, if not, you can just let that node do its thing and it will bring the database to a correct state (rebuild the ledger) after which you can try again. If it then starts instantly, you can use that database for your real node.

If you have messed with your database and run into the bug in the ticket, then you can follow the workaround: i.e., delete the snapshot with the highest number in your ledger folder and start up a node using the database. If you still run into the bug, repeat. In the end it either starts up after a short rebuild or you have to rebuild the ledger state from scratch.

Warning: if you're copying the database from a running node without wanting to shut it down, first copy the ledger folder and then the immutable folder. You could run into the bug when you do it in the opposite order.

You will run into the bug when a snapshot in the ledger folder is newer than the chain stored in the immutable folder. This never happens under normal circumstances, unless files from the immutable folder are missing (deleted or not copied) or manually copied a snapshot that is newer than the chain in the immutable folder.

Suggestion for a smooth upgrade: let's say you're running a block-producing 1.20.0 node called A pointed at the database in /db_a. Now you want to upgrade it to 1.21.1 with as little downtime as possible.

1. Copy /db_a to /db_b in the order I mentioned above: first ledger, then immutable. As immutable is the largest folder, you could first copy immutable, then ledger, and then rsync immutable again. It's not needed to copy volatile.
   UPDATE: also copy the protocolMagicId file.
2. Start a non-block producing 1.21.1 node called B pointed at /db_b. If it rebuilds the ledger state, let it.
3. When started, B will start syncing and will catch up with the current slot.
4. When in sync with network, shut B down and start B up again to verify that B can start quickly using /db_b.
   UPDATE: when shutting down a node, wait until it has fully started, i.e., until you have seen a message containing Opened db with immutable tip at ... A shutdown before this message won't be a clean shutdown, so the next start up might take longer and might even require rebuilding the ledger from scratch. After a clean shutdown, a file called clean will have appeared.
5. If B restarted quickly, you can be quite sure that it will restart quickly the next time too, especially if the next restart happens soon.
6. Shut down the non-block-producing 1.21.1 node B.
   UPDATE: make sure it was a clean shut down by checking for the existence of /db_b/clean.
7. Shut down the block-producing 1.20.0 node A.
8. Start node B (running 1.21.1) in block-producer mode, still pointed at `/db_b.
9. It will start up quickly and the downtime will be minimal.

The downtime happens between 7 and 8. The longer between 6 and 8, the more blocks it might have to resync, which should also be minimised.

For the next upgrade, do the same but swap A and B (or call them blue/green).

[AndrewWestberg]

Or you could just run leader logs with JorManager, the python script, or the NodeJS script and have a normal maintenance window with which to update a node in-place.

[rphair]

I didn't know the need to see block production schedules in advance had been addressed yet. What are "the" python script and "the" NodeJS script? Thanks & I'd be happy to see a specific reference. :smile:

_EDIT:_ I see something relevant here & will check it out (sorry for getting off topic): https://github.com/MarcelKlammer/cardano-leader-logs

[rphair]

@mrBliss we adapted the strategy in https://github.com/input-output-hk/cardano-node/issues/1944#issuecomment-706248855 to see if we could get a usable snapshot from running nodes, and just tested it on a running relay node (1.20.0) with a script like this:

nice rm -rf $DB_SNAP
mkdir $DB_SNAP
nice cp -pr $DB_LIVE/immutable $DB_SNAP/immutable
nice cp -pr $DB_LIVE/ledger $DB_SNAP/ledger
nice rsync -a $DB_LIVE/immutable/ $DB_SNAP/immutable

When we tried restarting the node with the snapshot DB, it failed to start normally with a stutter of this message (failing & restarting every 10+ seconds) in the log file:

[relay-sg:cardano.node.release:Notice:5] [2020-10-12 11:24:07.71 UTC] CardanoProtocol
NoDbMarkerAndNotEmpty "/home/spo/db/protocolMagicId"
cardano-node: Missing "/home/spo/db/protocolMagicId" but the folder was not empty
Listening on http://127.0.0.1:12798

When we added copying the protocolMagicId file to our snapshot script, it restarted bang-on from the snapshot. Some will know instinctively this file is to be copied, but to be rigorous you might please add it to the snapshot procedure. :sunglasses:

nice rm -rf $DB_SNAP
mkdir $DB_SNAP
nice cp -pr $DB_LIVE/immutable $DB_SNAP/immutable
nice cp -pr $DB_LIVE/ledger $DB_SNAP/ledger
nice rsync -a $DB_LIVE/immutable/ $DB_SNAP/immutable
cp -p $DB_LIVE/protocolMagicId $DB_SNAP/protocolMagicId

[rphair]

... an amendment to the last comment. The node only restarted immediately in the first test and one other. All other restarts of the node from the live snapshot had a 2½ to 3½ minute delay (on a dual processor server):

[relay-sg:cardano.node.release:Notice:5] [2020-10-12 12:22:15.62 UTC] CardanoProtocol ...
[relay-sg:cardano.node.ChainDB:Info:5] [2020-10-12 12:24:45.77 UTC] Opened vol db ...
[relay-sg:cardano.node.ChainDB:Info:5] [2020-10-12 12:24:48.89 UTC] block replay progress (%) = 100.0

I'll let this go if our software is now considered out of date and if it's fixed in 1.21.x and beyond, and don't want to divert this issue too much. Our best maintenance window isn't for 2+ weeks and I just wondering how best to be prepared in the meantime, and didn't want to give any false expectations about the live snapshots. We'll do your official procedure by hand if we ever get stuck. :disappointed:

[mrBliss]

@rphair I indeed forgot about protocolMagicId :facepalm:. The multi-minute wait you're seeing is because your shutdowns weren't clean, i.e., you likely shut down the node before it had fully started. I have updated my comment above (look for UPDATE:) with additional information about this. Thanks for trying it out!