VMware Cloud Community
WestCoastHiker
Contributor
Contributor

Resiliency of VMFS in event of power loss

Hi guys,

Long time reader, first time poster. Thanks for such an awesome community.

I have a ESXi 5.5-1331820 SuperMicro based box that is using a LSI MegaRAID Controller with BBU and write back is enabled. We had a short black out, lights flickered and only a few servers rebooted and this ESXi server was one of them.

It booted back up again, but any changes made after last Friday were corrupt. Any of the VM I created last week, the VMX files, everything looks borked. I can't seem to salvage VMDK's to a new VM.

VM's that were created prior to that (weeks/months before) look normal so far. There does not seem to be data loss there.

When it happened I did have an iSCSI LUN connected to my PC (which did not power cycle) that was from a CentOS VM and I was running IOMETER to bench it. Other than that the system was idle.

The weird thing is that particular VM is totally fine and the iSCSI LUN is still workable but it only had bunk test data on it. My 6+ other VM's that were idle are the effected ones. The correlation between these corrupt VM's is that they were all created last week on Friday. This power outage happened on Monday. My other VM's can boot up and seem fine so far.

When I try to tail the VMX file from the command line it throws invalid argument and when I try to import the VMDK to a new VM it says that one of the snapshots it relies on is missing.

I see some repeating errors in the vmkernel log

2014-09-23T08:44:49.039Z cpu45:214450)J3: 4378: Replaying transaction failed: Invalid metadata

2014-09-23T08:44:49.039Z cpu45:214450)J3: 4391:         checksum eed2ce4d370026b1, length 3072, CID 0xc1d00006, hbGen 9, ser# 13739

2014-09-23T08:44:49.039Z cpu45:214450)J3: 4393:         2 lockActions, first at 48

2014-09-23T08:44:49.039Z cpu45:214450)J3: 4395:         2 logActions, first at 848

2014-09-23T08:44:49.039Z cpu45:214450)J3: 4401: Locks

2014-09-23T08:44:49.039Z cpu45:214450)J3: 4405: #0: 52625408 v 0

2014-09-23T08:44:49.039Z cpu45:214450)J3: 4405: #1: 193269760 v 378

2014-09-23T08:44:49.039Z cpu45:214450)J3: 4407: Actions

2014-09-23T08:44:49.039Z cpu45:214450)J3: 4411: #0: type 1 reqLk 0, fr 0 to 52625920, len 512

2014-09-23T08:44:49.039Z cpu45:214450)J3: 4411: #1: type 1 reqLk 1, fr 0 to 193270272, len 1536

2014-09-23T08:44:49.039Z cpu45:214450)WARNING: J3: 4080: Replaying slot 0 for journal at <FB 8508200>: Invalid metadata

2014-09-23T08:44:49.039Z cpu45:214450)WARNING: HBX: 4755: Replay of journal <FB 8508200> on vol 'RAID10 (VM Datastore)' failed: Invalid metadata

2014-09-23T08:44:49.455Z cpu45:214450)HBX: 5410: Marking HB [HB state abcdef04 offset 4014080 gen 9 stampUS 68154025073 uuid 541c4c5f-8bdac1e0-e166-00259095885c jrnl <FB 8508200> drv 14.60] on vol 'RAID10 (VM Datastore)'

2014-09-23T08:44:49.455Z cpu45:214450)HBX: 5488: Marked HB [HB state abcdef04 offset 4014080 gen 9 stampUS 68154441425 uuid 541c4c5f-8bdac1e0-e166-00259095885c jrnl <FB 8508200> drv 14.60] on vol 'RAID10 (VM Datastore)'

2014-09-23T08:44:49.455Z cpu45:214450)J3: 3932: Replaying journal at <FB 8508200>, gen 9

Invalid lock address 0[lockAddr 0] Invalid lock type 0x0[lockAddr 193269760] Invalid lock addr 02014-09-23T08:44:49.455Z cpu45:214450)WARNING: DLX: 908: Volume 541c4eec-99d37420-909e-00259095885c ("RAID10 (VM Datastore)") might be damaged on the disk. Corrupt lock detected at offset b851000: [type 0 offset 0 v 0, hb offset 0

gen 0, mode 0,$

2014-09-23T08:44:49.455Z cpu45:214450)J3: 4378: Replaying transaction failed: Invalid metadata

2014-09-23T08:44:49.455Z cpu45:214450)J3: 4391:         checksum eed2ce4d370026b1, length 3072, CID 0xc1d00006, hbGen 9, ser# 13739

2014-09-23T08:44:49.455Z cpu45:214450)J3: 4393:         2 lockActions, first at 48

2014-09-23T08:44:49.455Z cpu45:214450)J3: 4395:         2 logActions, first at 848

2014-09-23T08:44:49.455Z cpu45:214450)J3: 4401: Locks

2014-09-23T08:44:49.455Z cpu45:214450)J3: 4405: #0: 52625408 v 0

2014-09-23T08:44:49.455Z cpu45:214450)J3: 4405: #1: 193269760 v 378

2014-09-23T08:44:49.455Z cpu45:214450)J3: 4407: Actions

2014-09-23T08:44:49.455Z cpu45:214450)J3: 4411: #0: type 1 reqLk 0, fr 0 to 52625920, len 512

2014-09-23T08:44:49.455Z cpu45:214450)J3: 4411: #1: type 1 reqLk 1, fr 0 to 193270272, len 1536

2014-09-23T08:44:49.455Z cpu45:214450)WARNING: J3: 4080: Replaying slot 0 for journal at <FB 8508200>: Invalid metadata

2014-09-23T08:44:49.455Z cpu45:214450)WARNING: HBX: 4755: Replay of journal <FB 8508200> on vol 'RAID10 (VM Datastore)' failed: Invalid metadata

2014-09-23T08:44:49.489Z cpu45:214450)HBX: 5410: Marking HB [HB state abcdef04 offset 4014080 gen 9 stampUS 68154441425 uuid 541c4c5f-8bdac1e0-e166-00259095885c jrnl <FB 8508200> drv 14.60] on vol 'RAID10 (VM Datastore)'

2014-09-23T08:44:49.489Z cpu45:214450)HBX: 5488: Marked HB [HB state abcdef04 offset 4014080 gen 9 stampUS 68154475423 uuid 541c4c5f-8bdac1e0-e166-00259095885c jrnl <FB 8508200> drv 14.60] on vol 'RAID10 (VM Datastore)'

2014-09-23T08:44:49.489Z cpu45:214450)J3: 3932: Replaying journal at <FB 8508200>, gen 9

Invalid lock address 0[lockAddr 0] Invalid lock type 0x0[lockAddr 193269760] Invalid lock addr 02014-09-23T08:44:49.489Z cpu45:214450)WARNING: DLX: 908: Volume 541c4eec-99d37420-909e-00259095885c ("RAID10 (VM Datastore)") might be damaged on the disk. Corrupt lock detected at offset b851000: [type 0 offset 0 v 0, hb offset 0

gen 0, mode 0,$

2014-09-23T08:44:49.489Z cpu45:214450)J3: 4378: Replaying transaction failed: Invalid metadata

2014-09-23T08:44:49.489Z cpu45:214450)J3: 4391:         checksum eed2ce4d370026b1, length 3072, CID 0xc1d00006, hbGen 9, ser# 13739

2014-09-23T08:44:49.489Z cpu45:214450)J3: 4393:         2 lockActions, first at 48

2014-09-23T08:44:49.489Z cpu45:214450)J3: 4395:         2 logActions, first at 848

2014-09-23T08:44:49.489Z cpu45:214450)J3: 4401: Locks

2014-09-23T08:44:49.489Z cpu45:214450)J3: 4405: #0: 52625408 v 0

2014-09-23T08:44:49.489Z cpu45:214450)J3: 4405: #1: 193269760 v 378

2014-09-23T08:44:49.489Z cpu45:214450)J3: 4407: Actions

2014-09-23T08:44:49.489Z cpu45:214450)J3: 4411: #0: type 1 reqLk 0, fr 0 to 52625920, len 512

2014-09-23T08:44:49.489Z cpu45:214450)J3: 4411: #1: type 1 reqLk 1, fr 0 to 193270272, len 1536

2014-09-23T08:44:49.489Z cpu45:214450)WARNING: J3: 4080: Replaying slot 0 for journal at <FB 8508200>: Invalid metadata

2014-09-23T08:44:49.489Z cpu45:214450)WARNING: HBX: 4755: Replay of journal <FB 8508200> on vol 'RAID10 (VM Datastore)' failed: Invalid metadata

2014-09-23T08:49:35.021Z cpu32:33199)usb storage warning (0 throttled) on vmhba32 (SCSI cmd TEST_UNIT_READY): command_abort called

                         usb storage message on vmhba32: Bulk data transfer result 0x0

                         usb storage message on vmhba32: scsi cmd done, result=0x2

                         usb storage message on vmhba32: Bulk command transfer result=0

2014-09-23T08:49:35.021Z cpu32:33199)usb storage warning (0 throttled) on vmhba32 (SCSI cmd TEST_UNIT_READY): usb_stor_stop_transport called

2014-09-23T08:49:35.021Z cpu38:33198)NMP: nmp_ThrottleLogForDevice:2321: Cmd 0x1a (0x412e82c29d40, 0) to dev "mpx.vmhba32:C0:T0:L0" on path "vmhba32:C0:T0:L0" Failed: H:0x5 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0. Act:EVAL

2014-09-23T08:49:35.021Z cpu38:33198)WARNING: NMP: nmp_DeviceRequestFastDeviceProbe:237: NMP device "mpx.vmhba32:C0:T0:L0" state in doubt; requested fast path state update...

2014-09-23T08:49:35.021Z cpu38:33198)ScsiDeviceIO: 2337: Cmd(0x412e82c29d40) 0x1a, CmdSN 0x3c70 from world 0 to dev "mpx.vmhba32:C0:T0:L0" failed H:0x5 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0.

Should I be terribly shocked that a server with a BBU backed RAID controller is susceptible to such wide spread data loss like this from a power outage?

I  have a couple of more specific questions too...

1.) Should I re-install ESXi to ensure nothing in the OS was borked that may be lying in wait for a later date?

2.) Is it worth trying to boot up a ubuntu CD and running the vmfs version of FSCK? I didn't lose anything important thankfully, this system is mostly just for doing tests, but I want to dig into this occurrence in case it were to come up in the future again so it is kind of like my little personal case study. I like to try and find something good out of a bad situation.

3.) Regardless of using fsck to try and salvage, should I re-create the datastores that were effected by this? The error below makes me worried that maybe the VMFS is in a bad way and I don't see any supported fsck utility outside of Ubuntu.

Invalid lock address 0[lockAddr 0] Invalid lock type 0x0[lockAddr 193269760] Invalid lock addr 02014-09-23T08:44:49.455Z cpu45:214450)WARNING: DLX: 908: Volume 541c4eec-99d37420-909e-00259095885c ("RAID10 (VM Datastore)") might be damaged on the disk. Corrupt lock detected at offset b851000: [type 0 offset 0 v 0, hb offset 0

gen 0, mode 0,$

4.) Does plain jane direct attached storage VMFS volumes always use sync writes like NFS or is it like iSCSI where it only sync writes the metadata?

An appropriately sized  UPS is in the works! I just inherited this whole system so I am improving things as I go along and this happened while starting to reconfigure the server basically.

I appreciate your time and I hope to hear your opinions and advice.

Reply
0 Kudos
1 Reply
continuum
Immortal
Immortal

Hi

first of all : are you missing any important *flat.vmdks or *-delta.vmdks ?

Corrupted vmx or vmdk-descriptorfiles often can be recovered with a few commands even if ESXi cant show them.
But if the large deltas and flats are missing you should check with vmfs-fuse as soon as possible.

2.)>>> Is it worth trying to boot up a ubuntu CD and running the vmfs version of FSCK?

There is no tool like "checkdisk" available for VMFS, that is able to fix errors, that I am aware of.
debugvmfs that comes with the vmfs-tools is a very valuable tool that helps guys that absolutely know what they are doing.
It will help someone who knows he has to truncate the file at offset 0x123456aa to fix the invalid pointer to fragment 267 of ...
I dont know anyone that regularly visits VMTN that has that skills (... and is willing to talk about it ! )

There exists voma on esxi 5.5 - but that does not really count as repair-tool - not at all.
Though VMFS is version 5.* already - there is no public repair-tool available.

Even more disapointing: after unexpected powerfailures of a busy VMFS you should not be surprised if ESXi can no longer read the volume at all.
If you are lucky its just the partitiontable that got wiped blank.
If you are not so lucky the table is still there but the volume became unmountable - or even unmountable after a resignature.
Single directories, single files and even complete volumes can appear blank after sudden powerfailure.

To read such a partly unreadable volume you often need other VMFS-reading tools besides  ESXi itself.
Probably you already noticed that a ESXi-host is not the best choice to use in such a case - not at all.
I do this kind of work regularly and my first pick is vmfs-fuse from Ubuntu-liveCDs or Centos-LiveCDs.
Sometimes I use ESXi LiveCDs which surprisingly have a better Read-success-rate then a full configured ESXi.



3 >> should I re-create the datastores that were effected by this?

. I tell all my customers that they should assume that they can not repair this type of errors once they occured so I recommend to move to a fresh VMFS volume as soon as possible.
On a new VMFS you can do a lot to prevent that future problems bite too much.

Show a vmfs header dump and I have a look ...

Ulli







________________________________________________
Do you need support with a VMFS recovery problem ? - send a message via skype "sanbarrow"
I do not support Workstation 16 at this time ...

Reply
0 Kudos