"Store upgrade failed" when upgrading Octez node from v15.1 to v16

Question

After updating our Docker image to v16 from v15.1, we see the following error in the logs after Octez shuts down:

Current public chain: 2018-06-30T16:07:32Z.
Local chain data: 2018-06-30T16:07:32Z.
Updating the node configuration...
Mar 21 18:16:32.983 - node.main: FULL access to RPC enabled; this is very risky.
Mar 21 18:16:32.983 - node.main:   (addresses = [::]:8732, 0.0.0.0:8737)
Mar 21 18:16:33.006 - node.config.validation: the node configuration has been successfully validated.
Mar 21 18:16:43.540 - node.data_version: upgrading data directory from 2.0 to 3.0
Mar 21 18:16:43.540 - node.store: upgrading the store
Mar 21 18:16:50.367 - node.store: store upgrade failed, cleaning up temporary files: Error:
Mar 21 18:16:50.367 - node.store:                                                      Not_found
Mar 21 18:16:50.367 - node.store: 
Mar 21 18:16:50.372 - node.data_version: failed to upgrade storage: Error:
Mar 21 18:16:50.372 - node.data_version:                              Not_found
Mar 21 18:16:50.372 - node.data_version: 
octez-node: Error:
              Not_found

Invoking the upgrade command directly using docker run -v mainnet-rolling_tezos-data:/var/run/tezos/node tezos/tezos:v16.0 octez-upgrade-storage runs into the same issue:

Current public chain: 2018-06-30T16:07:32Z.
Local chain data: 2018-06-30T16:07:32Z.
Mar 21 18:24:33.028 - node.data_version: upgrading data directory from 2.0 to 3.0
Mar 21 18:24:33.028 - node.store: upgrading the store
Mar 21 18:24:40.177 - node.store: store upgrade failed, cleaning up temporary files: Error:
Mar 21 18:24:40.177 - node.store:                                                      Not_found
Mar 21 18:24:40.177 - node.store: 
Mar 21 18:24:40.183 - node.data_version: failed to upgrade storage: Error:
Mar 21 18:24:40.183 - node.data_version:                              Not_found
Mar 21 18:24:40.183 - node.data_version: 
octez-node: Error:
              Not_found

This is a rolling node that is about a year old. It was synced from scratch.

UPDATE: Updating the Docker image to v16.1 did not fix the issues:

Current public chain: 2018-06-30T16:07:32Z.
Local chain data: 2018-06-30T16:07:32Z.
Updating the node configuration...
Mar 23 22:44:55.749 - node.main: FULL access to RPC enabled; this is very risky.
Mar 23 22:44:55.749 - node.main:   (addresses = [::]:8732, 0.0.0.0:8737)
Mar 23 22:44:55.797 - node.config.validation: the node configuration has been successfully validated.
Mar 23 22:45:06.290 - node.data_version: upgrading data directory from 2.0 to 3.0
Mar 23 22:45:06.290 - node.store: upgrading the store
Mar 23 22:45:13.716 - node.store: store upgrade failed, cleaning up temporary files:
Mar 23 22:45:13.716 - node.store:   Error:
Mar 23 22:45:13.716 - node.store:     Failed to upgrade block BMUMeUBzxMn3NJ272Ji8PWv2gD4rVTcUzqomMZxhpPs3FVhrHWd (level 3222226) for RO_TMP floating store: block not found in the index.
Mar 23 22:45:13.716 - node.store: 
Mar 23 22:45:13.722 - node.data_version: failed to upgrade storage:
Mar 23 22:45:13.722 - node.data_version:   Error:
Mar 23 22:45:13.722 - node.data_version:     Failed to upgrade block BMUMeUBzxMn3NJ272Ji8PWv2gD4rVTcUzqomMZxhpPs3FVhrHWd (level 3222226) for RO_TMP floating store: block not found in the index.
Mar 23 22:45:13.722 - node.data_version: 
octez-node: Error:
              Failed to upgrade block BMUMeUBzxMn3NJ272Ji8PWv2gD4rVTcUzqomMZxhpPs3FVhrHWd (level 3222226) for RO_TMP floating store: block not found in the index.

Any ideas on how we can get this working?

Answer 1

It seems that the node is in an unexpected state where a block is stored but not indexed. We could discard the upgrade of that block but it seems a better idea to start with a new storage thanks to a snapshot import. As you are using a rolling note, this will be very quick. Additionally, as your rolling node is running since a year, importing a snapshot will enable the garbage collection of the storage and will drastically reduce the disk usage of your node.