Data loss after version migration - Corrupt or incorrect page (1470)

[thememika]

Hello. I upgraded from out-of-tree KVDO to the in-kernel version on one of my systems. It went wrong and now KVDO doesn't work as intended. During the upgrade I had to use force rebuild because the recovery journal was "in the old format" It completed with some errors.

device-mapper: vdo: dm-vdo3:reqQ: Rebuilding reference counts to clear read-only mode
device-mapper: vdo: dm-vdo3:reqQ: Finished reading recovery journal
device-mapper: vdo: dm-vdo3:reqQ: Replaying 56305 recovery entries into block map
device-mapper: vdo: dm-vdo3:reqQ: Flushing block map changes
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9067993 but got page 679129 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9067994 but got page 679130 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9067995 but got page 679131 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9067996 but got page 679132 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9067997 but got page 679133 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9067998 but got page 679134 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9067999 but got page 679135 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068000 but got page 679136 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068001 but got page 679137 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068002 but got page 679138 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068003 but got page 679139 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068004 but got page 679140 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068005 but got page 679141 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068006 but got page 679142 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068007 but got page 679143 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068008 but got page 679144 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068009 but got page 679145 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068010 but got page 679146 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068011 but got page 679147 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068012 but got page 679148 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068013 but got page 679149 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068014 but got page 679150 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068015 but got page 679151 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068016 but got page 679152 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068017 but got page 679153 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068018 but got page 679154 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068019 but got page 679155 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068020 but got page 679156 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068021 but got page 679157 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068022 but got page 679158 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068023 but got page 679159 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068024 but got page 679160 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068025 but got page 679161 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068026 but got page 679162 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068027 but got page 679163 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068028 but got page 679164 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068029 but got page 679165 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068030 but got page 679166 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068031 but got page 679167 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068032 but got page 679168 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068033 but got page 679169 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068034 but got page 679170 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068035 but got page 679171 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068036 but got page 679172 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068037 but got page 679173 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068038 but got page 679174 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068039 but got page 679175 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068040 but got page 679176 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068041 but got page 679177 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068042 but got page 679178 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068043 but got page 679179 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068044 but got page 679180 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068045 but got page 679181 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068046 but got page 679182 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068047 but got page 679183 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068048 but got page 679184 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068049 but got page 679185 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068050 but got page 679186 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068051 but got page 679187 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Expected page 9068052 but got page 679188 instead: VDO Status: Corrupt or incorrect page (1470)
device-mapper: vdo: dm-vdo3:reqQ: Flushing block map changes
device-mapper: vdo: dm-vdo3:reqQ: Saving rebuilt state
device-mapper: vdo: dm-vdo3:reqQ: Read-only rebuild complete
device-mapper: vdo: dm-vdo3:reqQ: VDO commencing normal operation
device-mapper: vdo: dm-vdo3:reqQ: Setting UDS index target state to online
device-mapper: vdo3:dmsetup: device '253:1' started

But the device was started, so I didn't notice the errors first. I ran my fsck (bcachefs fsck, to be specific) on the DM-VDO device. After few seconds, the fsck crashed with an I/O error. This is what happened

device-mapper: vdo: dm-vdo4:reqQ: Decrementing free block at offset 41265 in slab 62: VDO Status: Reference count would become invalid (1466)
device-mapper: vdo: dm-vdo4:reqQ: Preparing to enter read-only mode: data_vio for LBN 1 (becoming mapped to 679189, previously mapped to 16973382, allocated 679189) is completing with a fatal error after operation update_reference_counts: VDO Status: Reference count would become invalid (1466)
device-mapper: vdo: dm-vdo4:reqQ: Unrecoverable error, entering read-only mode: VDO Status: Reference count would become invalid (1466)
device-mapper: vdo: dm-vdo4:reqQ: Completing write vio for LBN 1 with error after update_reference_counts: VDO Status: Reference count would become invalid (1466)
device-mapper: vdo: dm-vdo4:cpuQ: vdo_status_to_errno: mapping internal status code 1466 (VDO_REF_COUNT_INVALID: VDO Status: Reference count would become invalid) to EIO
device-mapper: vdo4:dmsetup: suspending device '253:1'
device-mapper: vdo: dm-vdo4:reqQ: beginning save (vcn 506)
device-mapper: vdo: dm-vdo4:reqQ: finished save (vcn 506)
device-mapper: vdo4:dmsetup: device '253:1' suspended

I retried force rebuild, and got the same "Expected page" errors once again during the rebuild. Once again, the device had started, though.

And it's now operating with no I/O errors, but I'm getting zeroes when trying to read the most important parts of my device, such as superblock:

# bcachefs fsck /dev/mapper/blossoms
bcachefs (/dev/mapper/blossoms): error reading default superblock: Not a bcachefs superblock (got magic 00000000-0000-0000-0000-000000000000)
bcachefs (/dev/mapper/blossoms): error reading superblock: Not a bcachefs superblock layout
#

How could it go like that, why? And is there any possibility of recovering data? My disks are fully operational, there are no media errors or damage. Everything was working fine before upgrade, how could this happen? Also, my other machines upgraded without any problems.

Here is some information about the setup, please ask more if needed:

su -c vdo-devel/src/c++/vdo/bin/vdoStats

Device   1k-blocks      Used Available Use% Space saving%
blossoms  83665348   3014008  80651340   4%            0%

note: it's invalid, my use% was 50+ % before migration

su -c vdo-devel/src/c++/vdo/user/vdoDumpConfig /dev/sda2

VDOConfig:
  blockSize: 4096
  logicalBlocks: 393216000
  physicalBlocks: 20916337
  slabSize: 262144
  recoveryJournalSize: 32768
  slabJournalBlocks: 224
IndexRegion: 1
DataRegion: 679128
IndexConfig:
  memory: 4294967040
  sparse: false

su -c vdo-devel/src/c++/vdo/bin/vdoStats -v

blossoms : 
  version                               : 36
  data blocks used                      : 0
  overhead blocks used                  : 753502
  logical blocks used                   : 0
  physical blocks                       : 20916337
  logical blocks                        : 393216000
  1K-blocks                             : 83665348
  1K-blocks used                        : 3014008
  1K-blocks available                   : 80651340
  used percent                          : 3
  saving percent                        : N/A
  block map cache size                  : 134217728
  block size                            : 4096
  completed recovery count              : 91
  read-only recovery count              : 4
  operating mode                        : normal
  recovery progress (%)                 : N/A
  compressed fragments written          : 0
  compressed blocks written             : 0
  compressed fragments in packer        : 0
  slab count                            : 77
  slabs opened                          : 0
  slabs reopened                        : 0
  journal disk full count               : 0
  journal commits requested count       : 0
  journal entries batching              : 0
  journal entries started               : 0
  journal entries writing               : 0
  journal entries written               : 0
  journal entries committed             : 0
  journal blocks batching               : 0
  journal blocks started                : 0
  journal blocks writing                : 0
  journal blocks written                : 0
  journal blocks committed              : 0
  slab journal disk full count          : 0
  slab journal flush count              : 0
  slab journal blocked count            : 0
  slab journal blocks written           : 0
  slab journal tail busy count          : 0
  slab summary blocks written           : 0
  reference blocks written              : 0
  block map dirty pages                 : 0
  block map clean pages                 : 6
  block map free pages                  : 32762
  block map failed pages                : 0
  block map incoming pages              : 0
  block map outgoing pages              : 0
  block map cache pressure              : 0
  block map read count                  : 7414
  block map write count                 : 0
  block map failed reads                : 0
  block map failed writes               : 0
  block map reclaimed                   : 0
  block map read outgoing               : 0
  block map found in cache              : 7205
  block map discard required            : 0
  block map wait for page               : 203
  block map fetch required              : 6
  block map pages loaded                : 6
  block map pages saved                 : 0
  block map flush count                 : 0
  dedupe advice valid                   : 0
  dedupe advice stale                   : 0
  concurrent data matches               : 0
  concurrent hash collisions            : 0
  current dedupe queries                : 0
  invalid advice PBN count              : 0
  no space error count                  : 0
  read only error count                 : 0
  instance                              : 1
  512 byte emulation                    : off
  current VDO IO requests in progress   : 0
  maximum VDO IO requests in progress   : 256
  dedupe advice timeouts                : 0
  flush out                             : 6
  write amplification ratio             : 0.00
  bios in read                          : 13068
  bios in write                         : 0
  bios in empty flush                   : 6
  bios in discard                       : 0
  bios in flush                         : 6
  bios in fua                           : 0
  bios in partial read                  : 0
  bios in partial write                 : 0
  bios in partial empty flush           : 0
  bios in partial discard               : 0
  bios in partial flush                 : 0
  bios in partial fua                   : 0
  bios out read                         : 236
  bios out write                        : 0
  bios out empty flush                  : 0
  bios out discard                      : 0
  bios out flush                        : 0
  bios out fua                          : 0
  bios meta read                        : 227
  bios meta write                       : 2
  bios meta empty flush                 : 0
  bios meta discard                     : 0
  bios meta flush                       : 1
  bios meta fua                         : 1
  bios journal read                     : 128
  bios journal write                    : 0
  bios journal empty flush              : 0
  bios journal discard                  : 0
  bios journal flush                    : 0
  bios journal fua                      : 0
  bios page cache read                  : 6
  bios page cache write                 : 0
  bios page cache empty flush           : 0
  bios page cache discard               : 0
  bios page cache flush                 : 0
  bios page cache fua                   : 0
  bios out completed read               : 236
  bios out completed write              : 0
  bios out completed empty flush        : 0
  bios out completed discard            : 0
  bios out completed flush              : 0
  bios out completed fua                : 0
  bios meta completed read              : 227
  bios meta completed write             : 1
  bios meta completed empty flush       : 1
  bios meta completed discard           : 0
  bios meta completed flush             : 1
  bios meta completed fua               : 0
  bios journal completed read           : 128
  bios journal completed write          : 0
  bios journal completed empty flush    : 0
  bios journal completed discard        : 0
  bios journal completed flush          : 0
  bios journal completed fua            : 0
  bios page cache completed read        : 6
  bios page cache completed write       : 0
  bios page cache completed empty flush : 0
  bios page cache completed discard     : 0
  bios page cache completed flush       : 0
  bios page cache completed fua         : 0
  bios acknowledged read                : 13068
  bios acknowledged write               : 0
  bios acknowledged empty flush         : 6
  bios acknowledged discard             : 0
  bios acknowledged flush               : 6
  bios acknowledged fua                 : 0
  bios acknowledged partial read        : 0
  bios acknowledged partial write       : 0
  bios acknowledged partial empty flush : 0
  bios acknowledged partial discard     : 0
  bios acknowledged partial flush       : 0
  bios acknowledged partial fua         : 0
  bios in progress read                 : 0
  bios in progress write                : 0
  bios in progress empty flush          : 0
  bios in progress discard              : 0
  bios in progress flush                : 0
  bios in progress fua                  : 0
  KVDO module bytes used                : 432370664
  KVDO module peak bytes used           : 432381160
  entries indexed                       : 29780006
  posts found                           : 0
  posts not found                       : 0
  queries found                         : 0
  queries not found                     : 0
  updates found                         : 0
  updates not found                     : 0
  entries discarded                     : 0

Thanks for any help!

[sweettea]

Hi thememika!

Very sorry to hear about these problems.

Force rebuild does carry a risk of data loss. Upgrade shouldn't have needed a force rebuild if the VDO was cleanly shut down, so I'm not sure what went wrong there. Unfortunately force-rebuild is destructive so the 50%->4% usage drop probably represents the amount of lost data, sadly.

I'm very disconcerted by the messages about a reference count decrement error during fsck after the force rebuild -- that should not happen.

One thing you could try doing is locating the bcachefs superblock on the device under VDO and then copying it to the right place on the VDO. This might allow bcachefs to mount, though there is likely other data loss with that 50% usage. You could try to locate it with blkid -p -O <4096 * i> -u filesystem -t TYPE=bcachefs /dev/<backing> for all values of i.

Maybe one of the actual vdo people has another idea?

-Sweet Tea (who hasn't worked on vdo in two years...)

[lorelei-sakai]

First off, I'm very sorry to hear about this situation.

From the messages it appears that the forced rebuild ran into some errors and as a result it has likely destroyed all the block mapping data on your device. (Technically much of the data is probably still there, but without the mappings it's unrecoverable, are there nothing to prevent further use of the device from overwriting it.) I hope you had backups. The vdoStats output is likely not invalid; instead the device really has no mapped content any more.

Forced rebuild is a very involved process, and it can result in the loss of data. If you have a backup or snapshot of the device before you ran the forced rebuild, we may be able to help you recover from that state.

As for why it happened, a VDO device needs to be shut down cleanly before it can be upgraded to the in-kernel version. Your other device were likely clean, so they encountered no issues. If you have any remaining VDO devices that you have not upgraded yet, make sure that you have shut them down cleanly before switching to the newer version.

The "corrupt page" error does concern me. I don't currently see how that could happen other than misbehavior from the storage layers below VDO, but I would still like to rule out a bug on our part. The fact that you can reproduce it is worrying. If you can provide the result of vdoDumpBlockMap for this device, it might help us understand what happened in more detail. It would also be helpful to know what version of VDO you were using before the upgrade, and whether you are using lvm to manage the VDO volume, or whether you're using dmsetup directly.

Also let us know if there's anything else we can do help.

[lorelei-sakai]

For anyone encountering this isue in the future, the "recovery journal in old format" message is the indicator that the VDO was not cleaned properly before upgrade. In that situation you should be able to switch back to the older version of VDO, do the recovery, and then upgrade safely.