Re: Datastore not available

Charles_Varvaya · ‎02-24-2013

Hello,

We are running EXSi 4.0.0 (294855) on a Dell PowerEdge 2800 with a PERC 4e/Di RAID Controller and three SCSI drives in a RAID 5 configuration.

We experienced a power anomaly where the power flashed on and off several times in rapid succession, but due to failed batteries in the UPS, the server was exposed to power anomaly.

After the event the server rebooted but the datastore was not available and as a result the virtual machines do not start.

------------------------------------------------------------------------------------------------------------

In the vSphere Client, after selecting the ESXi server, then the Configuration tab and then Storage, I see the datastore with one strange item:

datastore1

Local MegaRAID Disk (mpx.vmhba1:C0:T0:L0):3 *

62.75 GB

206.00 MB

vmfs3

2/24/2013 11:01:37 AM

* = Strange item # 1: I see Local MegaRAID Disk (mpx.vmhba1:C0:T0:L0):3 when I expect to see Local MegaRAID Disk (naa.xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx):3 where xxx… is some actual identifier

------------------------------------------------------------------------------------------------------------

When I click on datastore1 for additional detail it shows the following with two items seeming strange:

Location: /vmfs/volumes/4cdfecd0-af285957-4667-0011435a3247

Path Selection

Fixed (VMware)

Paths

Total: 1

Broken: 0

Disabled: 0

Properties

Volume Label: datastore1

Datastore Name: datastore1

Formating

File System: VNFS 3.33

Block Size: 1 MB

Extents

Local MegaRAID Disk (mpx.vmhba1:C0:T0:L0):3 0.00B **

Total Formatted Capacity 62.75 GB

** = Strange item # 2: I see Local MegaRAID Disk (mpx.vmhba1:C0:T0:L0):3 0.00B when I expect to see Local MegaRAID Disk (naa.xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx):3 62.75 GB where xxx… is some actual identifier and the capacity is 0.00 B. There are two strange things in this item: 1) The identifier seems wrong and, 2) the capacity is 0.00B.

------------------------------------------------------------------------------------------------------------

In the vSphere Client, after selecting the ESXi server, then the Configuration tab and then Storage Adapters, I see PowerEdge Expandable RAID Controller 4e/Di among other items. Just under that I see vmhba1 SCSI. When I click on vmhba1 SCSI 1 for additional detail it shows the following [Devices] with two items seeming strange:

Local MegaRAID Disk (mpx.vmhba1:C0:T0:L0) ***

mpx.vmhba1:C0:T0:L0 ***

vmhba1:C0:T0:L0 ****

0

Disk

Parallel SCSI

67.73 GB

NMP

*** = Strange item # 3: I see Local MegaRAID Disk (mpx.vmhba1:C0:T0:L0) when I expect to see Local MegaRAID Disk (naa.xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx) where xxx… is some actual identifier

**** = Strange item # 4: I see mpx.vmhba1:C0:T0:L0 when I expect to see naa.xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx where xxx… is some actual identifier

------------------------------------------------------------------------------------------------------------

When [Paths] is selected (from above location), I see what looks normal but with a twist:

vmhba1:C0:T0:L0

[BLANK]

0

Active (I/O)

If I right click and select copy path to clipboard then past it into notepad, I get slightly different result with one item seeming strange:

unknown.vmhba1-unknown.0:0-mpx.vmhba1:C0:T0:L0 *****

***** = Strange item # 5: I see unknown.vmhba1-unknown.0:0-mpx.vmhba1:C0:T0:L0 when I expect to see unknown.vmhba1-unknown.0:0-naa.xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx where xxx… is some actual identifier

------------------------------------------------------------------------------------------------------------

As can be seen, a consistent theme seems to exist. In places where one item is expected, another is present. Specifically, in those instances where naa.xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx is expected where xxx… is some actual identifier, mpx.vmhba1:C0:T0:L0 is present.

------------------------------------------------------------------------------------------------------------

The complete log files and this problem description are available at: www.varvayanis.com/vmware_problem_2-24-2013

What I expect is a significant clue, the /var/log/vmware/hostd.log log contains some interesting information. Below are the top 71 lines from that log with the first thing I notice as possibly strange beginning at line 56 and additional errors that get my attention are on lines 58,60,66,67 and 69. Many more “Looking up object with name = "ha-view-mgr-impl" failed.” errors occur throughout the log, but that is past the volume setup stuff below:

1) Log for VMware ESX, pid=4960, version=4.0.0, build=build-294855, option=Release, section=1

2) [2013-02-24 07:07:08.218 1FE74DB0 info 'App'] Current working directory: /var/log/vmware

3) [2013-02-24 07:07:08.219 1FE74DB0 verbose 'ThreadPool'] Thread info: Min Io, Max Io, Min Task, Max Task, Max Thread, Keepalive, thread kill, max fds: 2, 200, 2, 12, 42, 8, 600, 2048

4) [2013-02-24 07:07:08.219 1FE74DB0 info 'Handle checker'] Setting system limit of 2048

5) [2013-02-24 07:07:08.219 1FE74DB0 info 'Handle checker'] Set system limit to 2048

6) [2013-02-24 07:07:08.221 1FE74DB0 verbose 'App'] Executable directory: /etc/init.d

7) [2013-02-24 07:07:08.221 1FE74DB0 verbose 'App'] Plugin base directory: /lib/

😎 [2013-02-24 07:07:08.221 1FE74DB0 info 'App'] Trying blklistsvc

9) [2013-02-24 07:07:08.221 1FE74DB0 verbose 'App'] Plugin 0 statically linked

10) [2013-02-24 07:07:08.222 1FE74DB0 info 'BlklistsvcPlugin'] Block List Service Plugin initialized

11) [2013-02-24 07:07:08.222 1FE74DB0 info 'App'] Trying cimsvc

12) [2013-02-24 07:07:08.222 1FE74DB0 verbose 'App'] Plugin 1 statically linked

13) [2013-02-24 07:07:08.222 1FE74DB0 verbose 'Cimsvc'] Initializing cimsvc plugin

14) [2013-02-24 07:07:08.227 1FE74DB0 verbose 'Cimsvc'] Created CimManagerImpl

15) [2013-02-24 07:07:08.227 1FE74DB0 info 'App'] Trying directorysvc

16) [2013-02-24 07:07:08.227 1FE74DB0 verbose 'App'] Plugin 2 statically linked

17) [2013-02-24 07:07:08.227 1FE74DB0 verbose 'DirectorysvcPlugin'] Directory service initialized

18) [2013-02-24 07:07:08.228 1FE74DB0 verbose 'DirectorysvcPlugin'] Command: Esxtop created

19) [2013-02-24 07:07:08.235 1FE74DB0 verbose 'DirectorysvcPlugin'] Service added: Esxtop:

20) [2013-02-24 07:07:08.235 1FE74DB0 info 'DirectorysvcPlugin'] Plugin initialized

21) [2013-02-24 07:07:08.235 1FE74DB0 info 'App'] Trying hostsvc

22) [2013-02-24 07:07:08.235 1FE74DB0 verbose 'App'] Plugin 3 statically linked

23) [2013-02-24 07:07:08.235 1FE74DB0 verbose 'HostsvcPlugin'] CreateHostsvcFactory: mockup mode is false

24) [2013-02-24 07:07:08.236 1FE74DB0 info 'HostsvcPlugin'] Storage data synchronization policy set to invalidate_change

25) [2013-02-24 07:07:08.236 1FE74DB0 info 'Vmfs2UpgradeModeLock'] [Init] undoAttempts(15), timeoutMsec(2000)

26) [2013-02-24 07:07:08.237 1FE74DB0 verbose 'FSVolumeProvider'] FSVolumeVmkImplProvider::Start() called

27) [2013-02-24 07:07:08.237 1FE74DB0 error 'FSVolumeProvider'] FSVolumeVmkImplProvider::Start() called

28) [2013-02-24 07:07:08.237 1FE74DB0 verbose 'HostsvcPlugin'] Initializing resource pool tree

29) [2013-02-24 07:07:08.237 1FE74DB0 info 'HostsvcPlugin'] Resource pool configuration: /etc/vmware/hostd/pools.xml

30) [2013-02-24 07:07:08.238 1FE74DB0 verbose 'HostsvcPlugin'] Looking up VMkernel resource group 'host/user'

31) [2013-02-24 07:07:08.239 1FE74DB0 verbose 'HostsvcPlugin'] Initializing vms in resource pool tree

32) [2013-02-24 07:07:08.240 1FE74DB0 verbose 'NetworkProvider'] Fetch all physical NICs....

33) [2013-02-24 07:07:09.331 1FE74DB0 verbose 'NetworkProvider'] Fetched physical NIC: vmnic0.

34) [2013-02-24 07:07:09.397 1FE74DB0 verbose 'NetworkProvider'] Fetched physical NIC: vmnic1.

35) [2013-02-24 07:07:09.397 1FE74DB0 verbose 'NetworkProvider'] Loading DVS information

36) [2013-02-24 07:07:09.397 1FE74DB0 verbose 'NetworkProvider'] DvsVmkProvider::Refresh called

37) [2013-02-24 07:07:09.398 1FE74DB0 warning 'NetworkProvider'] Failed to load DVS portgroup information : no element found.

38) [2013-02-24 07:07:09.398 1FE74DB0 verbose 'NetworkProvider'] Fetch all virtual switches....

39) [2013-02-24 07:07:09.725 1FE74DB0 verbose 'NetworkProvider'] Successfully fetched virtual switch: vSwitch0.

40) [2013-02-24 07:07:09.726 1FE74DB0 verbose 'NetworkProvider'] RefreshVmkernelNic: called

41) [2013-02-24 07:07:09.748 1FE74DB0 verbose 'NetworkProvider'] InstallNics: Fetch all VmKernel NICs....

42) [2013-02-24 07:07:09.770 1FE74DB0 verbose 'NetworkProvider'] InstallNics: Successfully fetched VmKernel NIC vmk0 on Management Network.

43) [2013-02-24 07:07:09.771 1FE74DB0 verbose 'NetworkProvider'] RefreshConsoleNic: Fetch all Console NICs....

44) [2013-02-24 07:07:09.792 1FE74DB0 verbose 'NetworkProvider'] All vnics refreshed, found 0 disabled.

45) [2013-02-24 07:07:09.792 1FE74DB0 verbose 'NetworkProvider'] Obtaining DNS Configuration....

46) [2013-02-24 07:07:09.795 1FE74DB0 verbose 'NetworkProvider'] Dns Configuration: Network::DnsConfig { GetHostname(): localhost, GetPreferredHostname():, GetDomain(): varvayanis.com, [0] 147.78.249.200, [1] 148.78.249.201, [0] varvayanis.com, GetSearchDomainString(): varvayanis.com, GetName(): DnsConfigImpl} }

47) [2013-02-24 07:07:09.795 1FE74DB0 verbose 'NetworkProvider'] Obtaining Route Configuration....

48) [2013-02-24 07:07:09.796 1FE74DB0 info 'NetworkProvider'] SetIPv6Capability: IPv6 is disabled

49) [2013-02-24 07:07:09.796 1FE74DB0 info 'HostsvcPlugin'] Datastore auto-refresh is disabled.

50) [2013-02-24 07:07:09.796 1FE74DB0 info 'Hostsvc::DatastoreSystem'] Datastore alias configuration file is /etc/vmware/hostd/datastores.xml

51) [2013-02-24 07:07:09.797 1FE74DB0 verbose 'Hostsvc::DatastoreSystem'] ReconcileVMFSDatastores called: refresh = true, rescan = false

52) [2013-02-24 07:07:09.797 1FE74DB0 verbose 'FSVolumeProvider'] RefreshVMFSVolumes called

53) [2013-02-24 07:07:09.882 1FE74DB0 verbose 'FSVolumeProvider'] RefreshVMFSVolumes: refreshed volume, id 4cdfecd0-af285957-4667-0011435a3247, name datastore1

54) [2013-02-24 07:07:09.882 1FE74DB0 verbose 'FSVolumeProvider'] RefreshOneVmfsVolume on /vmfs/volumes/4cdfecd0-af285957-4667-0011435a3247

55) [2013-02-24 07:07:09.885 1FE74DB0 info 'Hostsvc::Datastore'] Refresh: VMFS Datastore name was changed from '4cdfecd0-af285957-4667-0011435a3247' to 'datastore1'.

56) [2013-02-24 07:07:09.885 1FE74DB0 verbose 'App'] Looking up object with name = "ha-vmsvc" failed.

57) [2013-02-24 07:07:09.886 1FE74DB0 verbose 'DatastoreBrowser'] 4cdfecd0-af285957-4667-0011435a3247-datastorebrowser::IntializeCOSDirectory: COS path: /vmimages/

58) [2013-02-24 07:07:09.886 1FE74DB0 verbose 'App'] Looking up object with name = "ha-view-mgr-impl" failed.

59) [2013-02-24 07:07:09.886 1FE74DB0 verbose 'DatastoreBrowser'] 4cdfecd0-af285957-4667-0011435a3247-datastorebrowser::Constructor

60) [2013-02-24 07:07:09.886 1FE74DB0 verbose 'App'] Looking up object with name = "ha-view-mgr-impl" failed.

61) [2013-02-24 07:07:09.886 1FE74DB0 verbose 'Hostsvc::DatastoreSystem'] DiscoverNewDatastores: datastore1 created.

62) [2013-02-24 07:07:09.886 1FE74DB0 verbose 'Hostsvc::DatastoreSystem'] ReconcileVMFSDatastores: Done discovering new filesystem volumes.

63) [2013-02-24 07:07:09.886 1FE74DB0 verbose 'Hostsvc::DatastoreSystem'] ReconcileNASDatastores: Discovering new filesystem volumes.

64) [2013-02-24 07:07:09.886 1FE74DB0 verbose 'FSVolumeProvider'] RefreshNASVolumes called

65) [2013-02-24 07:07:09.909 1FE74DB0 verbose 'Hostsvc::DatastoreSystem'] ReconcileNASDatastores: Done discovering new filesystem volumes.

66) [2013-02-24 07:07:22.642 1FE74DB0 verbose 'App'] Looking up object with name = "ha-view-mgr-impl" failed.

67) [2013-02-24 07:07:22.642 1FE74DB0 verbose 'App'] Looking up object with name = "ha-vmsvc" failed.

68) [2013-02-24 07:07:22.643 1FE74DB0 verbose 'DatastoreBrowser'] ha-host-datastorebrowser::IntializeCOSDirectory: COS path: /vmimages/

69) [2013-02-24 07:07:22.643 1FE74DB0 verbose 'App'] Looking up object with name = "ha-view-mgr-impl" failed.

70) [2013-02-24 07:07:22.643 1FE74DB0 verbose 'DatastoreBrowser'] ha-host-datastorebrowser::Constructor

71) [2013-02-24 07:07:22.643 1FE74DB0 info 'Hostsvc::AutoStartManager'] VM autostart configuration: /etc/vmware/hostd/vmAutoStart.xml

------------------------------------------------------------------------------------------------------------

The complete log files and this problem description are available at: www.varvayanis.com/vmware_problem_2-24-2013

What I expect is also a clue, the /var/log/Messages.log log contains some interesting information. Below are 115 lines starting at line 1439 from that log with the first item that got my attention at line 1479 and additional items that got my attention are on lines 1481, 1526, 1528, 1532 and 1533:

1439) Feb 24 07:06:50 vmkernel: 0:00:00:38.869 cpu2:4551)ata_piix loaded successfully.

1440) Feb 24 07:06:50 vmkernel:

1441) Feb 24 07:06:52 vmkernel: 0:00:00:40.717 cpu2:4554)Loading module megaraid2 ...

1442) Feb 24 07:06:52 vmkernel: 0:00:00:40.717 cpu2:4554)Elf: 2320: <megaraid2> symbols tagged as <GPL>

1443) Feb 24 07:06:52 vmkernel: 0:00:00:40.739 cpu2:4554)module heap : Initial heap size : 8388608, max heap size: 20971520

1444) Feb 24 07:06:52 vmkernel: 0:00:00:40.739 cpu2:4554)module heap megaraid2: creation succeeded. id = 0x4100b2000000

1445) Feb 24 07:06:52 vmkernel: 0:00:00:40.739 cpu2:4554)PCI: driver megaraid2 is looking for devices

1446) Feb 24 07:06:52 vmkernel: 0:00:00:40.739 cpu2:4554)PCI: Trying 0000:00:02.0

1447) Feb 24 07:06:52 vmkernel: 0:00:00:40.739 cpu2:4554)PCI: Announcing 0000:00:02.0

1448) Feb 24 07:06:52 vmkernel: 0:00:00:40.739 cpu2:4554)PCI: Trying 0000:00:03.0

1449) Feb 24 07:06:52 vmkernel: 0:00:00:40.739 cpu2:4554)PCI: Announcing 0000:00:03.0

1450) Feb 24 07:06:52 vmkernel: 0:00:00:40.739 cpu2:4554)PCI: Trying 0000:00:04.0

1451) Feb 24 07:06:52 vmkernel: 0:00:00:40.739 cpu2:4554)PCI: Announcing 0000:00:04.0

1452) Feb 24 07:06:52 vmkernel: 0:00:00:40.739 cpu2:4554)PCI: Trying 0000:00:05.0

1453) Feb 24 07:06:52 vmkernel: 0:00:00:40.739 cpu2:4554)PCI: Announcing 0000:00:05.0

1454) Feb 24 07:06:52 vmkernel: 0:00:00:40.739 cpu2:4554)PCI: Trying 0000:00:06.0

1455) Feb 24 07:06:52 vmkernel: 0:00:00:40.739 cpu2:4554)PCI: Announcing 0000:00:06.0

1456) Feb 24 07:06:52 vmkernel: 0:00:00:40.739 cpu2:4554)PCI: Trying 0000:00:1d.0

1457) Feb 24 07:06:52 vmkernel: 0:00:00:40.739 cpu2:4554)PCI: Trying 0000:00:1d.1

1458) Feb 24 07:06:52 vmkernel: 0:00:00:40.739 cpu2:4554)PCI: Trying 0000:00:1d.2

1459) Feb 24 07:06:52 vmkernel: 0:00:00:40.739 cpu2:4554)PCI: Trying 0000:00:1d.7

1460) Feb 24 07:06:52 vmkernel: 0:00:00:40.739 cpu2:4554)PCI: Trying 0000:00:1f.1

1461) Feb 24 07:06:52 vmkernel: 0:00:00:40.739 cpu2:4554)PCI: Trying 0000:02:0e.0

1462) Feb 24 07:06:52 vmkernel: 0:00:00:40.739 cpu2:4554)PCI: Announcing 0000:02:0e.0

1463) Feb 24 07:06:52 vmkernel: <5>megaraid: found 0x1028:0x 0013:bus 2:0:00:00:40.739 cpu2:4554)slot 14:func 0

1464) Feb 24 07:06:52 vmkernel: 0:00:00:40.740 cpu2:4554)<5>scsi2:Found MegaRAID controller at 0x4100b2a02000, IRQ:153

1465) Feb 24 07:06:52 vmkernel: 0:00:00:40.740 cpu2:4554)IDT: 939: 0x99 <megaraid> sharable (entropy source), flags 0x10

1466) Feb 24 07:06:52 vmkernel: 0:00:00:40.740 cpu2:4554)VMK_VECTOR: 143: Added handler for shared vector 153, flags 0x10

1467) Feb 24 07:06:52 vmkernel: 0:00:00:40.740 cpu2:4554)IDT: 1035: 0x99 for vmkernel

1468) Feb 24 07:06:52 vmkernel: 0:00:00:40.740 cpu2:4554)VMK_VECTOR: 231: vector 153 enabled

1469) Feb 24 07:06:52 vmkernel: 0:00:00:40.740 cpu2:4554)<5>megaraid: [5B2D:H435] detected 1 logical drives.

1470) Feb 24 07:06:52 vmkernel: 0:00:00:40.740 cpu2:4554)<5>megaraid: supports extended CDBs.

1471) Feb 24 07:06:52 vmkernel: 0:00:00:40.744 cpu2:4554)<6>megaraid: channel[0] is raid.

1472) Feb 24 07:06:52 vmkernel: 0:00:00:40.744 cpu2:4554)<6>megaraid: channel[1] is scsi.

1473) Feb 24 07:06:52 vmkernel: 0:00:00:40.744 cpu2:4554)VMK_PCI: 638: Device 002:14.0 name: vmhba1

1474) Feb 24 07:06:52 vmkernel: <5>scsi2: scanning scsi channel 0 0:00:00:40.744 cpu2:4554)for logical drives.

1475) Feb 24 07:06:52 vmkernel: 0:00:00:40.744 cpu2:4554)ScsiScan: 844: Path 'vmhba1:C0:T0:L0': Vendor: 'MegaRAID' Model: 'LD 0 RAID5 69G' Rev: '5B2D'

1476) Feb 24 07:06:52 vmkernel: 0:00:00:40.744 cpu2:4554)ScsiScan: 847: Path 'vmhba1:C0:T0:L0': Type: 0x0, ANSI rev: 2, TPGS: 0 (none)

1477) Feb 24 07:06:52 vmkernel: 0:00:00:40.752 cpu0:4550)EVPD INQ host status changed to DID_OK

1478) Feb 24 07:06:52 vmkernel: 0:00:00:40.752 cpu2:4554)ScsiUid: 268: Path 'vmhba1:C0:T0:L0' does not support VPD Device Id page.

1479) Feb 24 07:06:52 vmkernel: 0:00:00:40.752 cpu2:4554)ScsiScan: 959: Path 'vmhba1:C0:T0:L0' : No standard UID: Failure. ANSI version 'SCSI-2' (0x2).

1480) Feb 24 07:06:52 vmkernel: 0:00:00:40.760 cpu0:4550)EVPD INQ host status changed to DID_OK

1481) Feb 24 07:06:52 vmkernel: 0:00:00:40.760 cpu2:4554)VMWARE SCSI Id: Could not get disk id for vmhba1:C0:T0:L0

1482) Feb 24 07:06:52 vmkernel: <5>scsi2: scanning scsi channel 1 0:00:00:40.766 cpu0:4554)for logical drives.

1483) Feb 24 07:06:52 vmkernel: <5>scsi2: scanning scsi channel 2 0:00:00:40.794 cpu1:4554)for logical drives.

1484) Feb 24 07:06:52 vmkernel: 0:00:00:41.009 cpu0:4554)ScsiClaimrule: 1118: Path claiming is disabled. Do not try to claim path.

1485) Feb 24 07:06:52 vmkernel: 0:00:00:41.009 cpu0:4554)PCI: driver megaraid2 claimed device 0000:02:0e.0

1486) Feb 24 07:06:52 vmkernel: 0:00:00:41.009 cpu0:4554)LinPCI: LinuxPCI_DeviceClaimed: Device 2:70 claimed.

1487) Feb 24 07:06:52 vmkernel:

1488) Feb 24 07:06:52 vmkernel: 0:00:00:41.009 cpu0:4554)PCI: Trying 0000:0b:07.0

1489) Feb 24 07:06:52 vmkernel: 0:00:00:41.009 cpu0:4554)PCI: Trying 0000:0c:08.0

1490) Feb 24 07:06:52 vmkernel: 0:00:00:41.009 cpu0:4554)PCI: Trying 0000:10:0d.0

1491) Feb 24 07:06:52 vmkernel: 0:00:00:41.009 cpu0:4554)PCI: Announcing 0000:10:0d.0

1492) Feb 24 07:06:52 vmkernel: 0:00:00:41.009 cpu0:4554)PCI: driver megaraid2 claimed 1 device

1493) Feb 24 07:06:52 vmkernel: 0:00:00:41.009 cpu0:4554)ScsiNpiv: 1440: GetInfo for adapter vmhba1, [0x41000403d2c0], max_vports=0, vports_inuse=0, linktype=0, state=0, failreason=0, rv=-1, sts=bad0020

1494) Feb 24 07:06:52 vmkernel: 0:00:00:41.009 cpu0:4554)Mod: 3003: Initialization for megaraid2 succeeded with module ID 34.

1495) Feb 24 07:06:52 vmkernel: 0:00:00:41.009 cpu0:4554)megaraid2 loaded successfully.

1496) Feb 24 07:06:52 vmkernel:

1497) Feb 24 07:06:53 vmkernel: sysboot: Loading VMkernel Module 'lvmdriver'

1498) Feb 24 07:06:53 vmkernel: 0:00:00:41.934 cpu3:4560)Loading module lvmdriver ...

1499) Feb 24 07:06:53 vmkernel: 0:00:00:41.934 cpu3:4560)Elf: 2320: <lvmdriver> symbols tagged as <VMware>

1500) Feb 24 07:06:53 vmkernel: 0:00:00:41.956 cpu3:4560)LVM: 782: LVM max heap size: 43008KB

1501) Feb 24 07:06:53 vmkernel: 0:00:00:41.956 cpu3:4560)FDS: 337: lvm

1502) Feb 24 07:06:53 vmkernel: 0:00:00:41.956 cpu3:4560)Mod: 3003: Initialization for lvmdriver succeeded with module ID 35.

1503) Feb 24 07:06:53 vmkernel: 0:00:00:41.956 cpu3:4560)lvmdriver loaded successfully.

1504) Feb 24 07:06:53 vmkernel:

1505) Feb 24 07:06:53 vmkernel: sysboot: Loading VMkernel Module 'deltadisk'

1506) Feb 24 07:06:53 vmkernel: 0:00:00:42.046 cpu1:4566)Loading module deltadisk ...

1507) Feb 24 07:06:53 vmkernel: 0:00:00:42.046 cpu1:4566)Elf: 2320: <deltadisk> symbols tagged as <VMware>

1508) Feb 24 07:06:53 vmkernel: 0:00:00:42.075 cpu1:4566)FDS: 337: deltadisks

1509) Feb 24 07:06:53 vmkernel: 0:00:00:42.075 cpu1:4566)Mod: 3003: Initialization for deltadisk succeeded with module ID 36.

1510) Feb 24 07:06:53 vmkernel: 0:00:00:42.075 cpu1:4566)deltadisk loaded successfully.

1511) Feb 24 07:06:53 vmkernel:

1512) Feb 24 07:06:53 vmkernel: sysboot: Loading VMkernel Module 'multiextent'

1513) Feb 24 07:06:53 vmkernel: 0:00:00:42.164 cpu2:4572)Loading module multiextent ...

1514) Feb 24 07:06:53 vmkernel: 0:00:00:42.164 cpu2:4572)Elf: 2320: <multiextent> symbols tagged as <VMware>

1515) Feb 24 07:06:53 vmkernel: 0:00:00:42.186 cpu2:4572)FDS: 337: multiextent

1516) Feb 24 07:06:53 vmkernel: 0:00:00:42.186 cpu2:4572)Mod: 3003: Initialization for multiextent succeeded with module ID 37.

1517) Feb 24 07:06:53 vmkernel: 0:00:00:42.186 cpu2:4572)multiextent loaded successfully.

1518) Feb 24 07:06:53 vmkernel:

1519) Feb 24 07:06:53 vmkernel: sysboot: Starting Path Claiming and SCSI Device Discovery...

1520) Feb 24 07:06:53 vmkernel: sysboot: Executing 'esxcli corestorage claimrule load'

1521) Feb 24 07:06:54 vmkernel: sysboot: Executing 'esxcli corestorage claiming autoclaim --enabled=true'

1522) Feb 24 07:06:54 vmkernel: sysboot: Executing 'esxcli corestorage claimrule run --wait'

1523) Feb 24 07:06:57 vmkernel: 0:00:00:45.398 cpu0:4583)ScsiPath: 3715: Plugin 'NMP' claimed path 'vmhba0:C0:T0:L0'

1524) Feb 24 07:06:57 vmkernel: 0:00:00:45.398 cpu0:4583)ScsiPath: 3715: Plugin 'NMP' claimed path 'vmhba1:C0:T0:L0'

1525) Feb 24 07:06:57 vmkernel: 0:00:00:45.406 cpu0:4583)EVPD INQ host status changed to DID_OK

1526) Feb 24 07:06:57 vmkernel: 0:00:00:45.406 cpu0:4583)ScsiUid: 268: Path 'vmhba1:C0:T0:L0' does not support VPD Device Id page.

1527) Feb 24 07:06:57 vmkernel: 0:00:00:45.414 cpu0:4583)EVPD INQ host status changed to DID_OK

1528) Feb 24 07:06:57 vmkernel: 0:00:00:45.414 cpu0:4583)VMWARE SCSI Id: Could not get disk id for vmhba1:C0:T0:L0

1529) Feb 24 07:06:57 vmkernel: 0:00:00:45.414 cpu0:4583)vmw_psp_fixed: psp_fixedSelectPathToActivateInt: Changing active path from NONE to vmhba1:C0:T0:L0 for device "Unregistered Device".

1530) Feb 24 07:06:57 vmkernel: 0:00:00:45.422 cpu0:4583)EVPD INQ host status changed to DID_OK

1531) Feb 24 07:06:57 vmkernel: 0:00:00:45.422 cpu0:4583)VMWARE SCSI Id: Could not get disk id for vmhba1:C0:T0:L0

1532) Feb 24 07:06:57 vmkernel: 0:00:00:45.422 cpu0:4583)ScsiDeviceIO: 2469: Get VPD 80 Inquiry for device "mpx.vmhba1:C0:T0:L0" from Plugin "NMP" failed. Not supported

1533) Feb 24 07:06:57 vmkernel: 0:00:00:45.422 cpu0:4583)ScsiDeviceIO: 2479: Get VPD 83 Inquiry for device "mpx.vmhba1:C0:T0:L0" from Plugin "NMP" failed. Not supported

1534) Feb 24 07:06:57 vmkernel: 0:00:00:45.489 cpu0:4583)FSS: 3702: No FS driver claimed device '4cdfecd0-88651ba4-fa57-0011435a3247': Not supported

1535) Feb 24 07:06:57 vmkernel: 0:00:00:45.525 cpu0:4583)ScsiDevice: 1938: Successfully registered device "mpx.vmhba1:C0:T0:L0" from plugin "NMP" of type 0

1536) Feb 24 07:06:57 vmkernel: 0:00:00:45.528 cpu0:4583)ScsiUid: 268: Path 'vmhba0:C0:T0:L0' does not support VPD Device Id page.

1537) Feb 24 07:06:57 vmkernel: 0:00:00:45.529 cpu0:4583)VMWARE SCSI Id: Could not get disk id for vmhba0:C0:T0:L0

1538) Feb 24 07:06:57 vmkernel: 0:00:00:45.529 cpu0:4583)vmw_psp_fixed: psp_fixedSelectPathToActivateInt: Changing active path from NONE to vmhba0:C0:T0:L0 for device "Unregistered Device".

1539) Feb 24 07:06:57 vmkernel: 0:00:00:45.530 cpu0:4583)VMWARE SCSI Id: Could not get disk id for vmhba0:C0:T0:L0

1540) Feb 24 07:06:57 vmkernel: 0:00:00:45.530 cpu0:4583)ScsiDeviceIO: 2469: Get VPD 80 Inquiry for device "mpx.vmhba0:C0:T0:L0" from Plugin "NMP" failed. Not supported

1541) Feb 24 07:06:57 vmkernel: 0:00:00:45.530 cpu0:4583)ScsiDeviceIO: 2479: Get VPD 83 Inquiry for device "mpx.vmhba0:C0:T0:L0" from Plugin "NMP" failed. Not supported

1542) Feb 24 07:06:57 vmkernel: 0:00:00:45.530 cpu0:4583)ScsiDevice: 1938: Successfully registered device "mpx.vmhba0:C0:T0:L0" from plugin "NMP" of type 5

1543) Feb 24 07:07:00 vmkernel: sysboot: Path Claiming and SCSI Device Discovery Complete

1544) Feb 24 07:07:00 vmkernel: sysboot: Executing 'esxcfg-mpath -r'

1545) Feb 24 07:07:00 vmkernel: sysboot: Loading VMkernel Module 'dvsdev'

1546) Feb 24 07:07:00 vmkernel: 0:00:00:48.773 cpu2:4594)Loading module dvsdev ...

1547) Feb 24 07:07:00 vmkernel: 0:00:00:48.774 cpu2:4594)Elf: 2320: <dvsdev> symbols tagged as <VMware>

1548) Feb 24 07:07:00 vmkernel: 0:00:00:48.796 cpu2:4594)Mod: 3003: Initialization for dvsdev succeeded with module ID 38.

1549) Feb 24 07:07:00 vmkernel: 0:00:00:48.796 cpu2:4594)dvsdev loaded successfully.

1550) Feb 24 07:07:00 vmkernel:

1551) Feb 24 07:07:00 vmkernel: sysboot: Loading VMkernel Module 'etherswitch'

1552) Feb 24 07:07:00 vmkernel: 0:00:00:48.893 cpu2:4600)Loading module etherswitch ...

1553) Feb 24 07:07:00 vmkernel: 0:00:00:48.893 cpu2:4600)Elf: 2320: <etherswitch> symbols tagged as <VMware>

------------------------------------------------------------------------------------------------------------

At the CLI I issued the command:

esxcfg-mpath.pl -l --server 10.145.0.2 --username xxxx --password xxx

and received the response:

ide.vmhba0-ide.0:0-mpx.vmhba0:C0:T0:L0

Runtime Name: vmhba0:C0:T0:L0

Device: mpx.vmhba0:C0:T0:L0

Device Display Name: Local TEAC CD-ROM (mpx.vmhba0:C0:T0:L0)

Adapter: vmhba0 Channel: 0 Target: 0 LUN: 0

Adapter Identifier: ide.vmhba0

Target Identifier: ide.0:0

Plugin: NMP

State: active

Transport: ide

unknown.vmhba1-unknown.0:0-mpx.vmhba1:C0:T0:L0

Runtime Name: vmhba1:C0:T0:L0

Device: mpx.vmhba1:C0:T0:L0

Device Display Name: Local MegaRAID Disk (mpx.vmhba1:C0:T0:L0)

Adapter: vmhba1 Channel: 0 Target: 0 LUN: 0

Adapter Identifier: unknown.vmhba1

Target Identifier: unknown.0:0

Plugin: NMP

State: active

Transport: parallel

------------------------------------------------------------------------------------------------------------

At the very bottom of an article I found, there is something that sounds relevant to this situation, but it is in a format that seems to relevant to ESX and maybe not ESXi. If it is relevant ESXi, I do not know how to implement it.

Here is the link:

communities.vmware.com/thread/303695 (Very bottom of the article).

------------------------------------------------------------------------------------------------------------

I am also receiving a lot of these messages: “Lost access to volume 4cdfecd0-af285957-4667-0011435a3247 (datastore1) due to connectivity issues. Recovery attempt is in progress and outcome will be reported shortly.” I found an article that may be relevant, but it has not helped me yet.

Here is the link:

kb.vmware.com/selfservice/microsites/search.do?language=en_US&cmd=displayKC&externalId=1009557

------------------------------------------------------------------------------------------------------------

I am stuck. Any help would be much appreciated.

Thank you,

Charles Varvayanis

Ytsejamer1 · ‎02-25-2013

I tried parsing through all your details, but I'm going to ask a couple more questions.

What is the status of your RAID 5 array that you were presenting out as a datastore in VMWare? Is it healthy or is it presenting an individual member disk up to ESXi?

With things not working correctly, I'd reboot the host and get into the controller to find out the status of that array. I wonder if the array is degraded or some settings on the controller were lost (you DID say you had dead/bad batteries)...hence why the RAID 5 array is no longer being presented as a whole, up to ESXi.

vSchu · ‎02-25-2013

I have more background with HP hardware but I have had a similar issue. Some raid cards will lock out the drives after a hard shutdown because there is "data in the local cache" that will be discarded if it loads. This is suppose to keep you from corrupting data. On hp I had to go into the raid controller settings on boot and select to clear the cache. From there everything comes up.

Donald Schubot | VCAP5-DCA, VCP4/5 | Blog: http://vschu.com/

Charles_Varvaya · ‎02-25-2013

Hello Ytsejamer1,

Here is information about the RAID:

From the vSphere client, RAID status is: Deassert

From the RAID BIOS status is: Optimal

From the RAID BIOS: All three Drives show as on line.

From the RAID BIOS: There is a total of one Logical Drive of maximum size.

Whereas there is a total of one Logical Drive of maximum size being presented by the RAID controller and whereas EXSi boots, I am comfortable that the RAID healthy.

Thank you,

Charles Varvayanis

alt="Charles Varvayanis" border=0>Charles Varvayanis

Computer and Communication Systems

P.O. Box 395, Long Barn, CA 95335-0395

Phone: (209) 586-3782 l Fax: (209) 586-3761

charles@varvayanis.com<mailto:charles@varvayanis.com> l www.varvayanis.com<http://www.varvayanis.com/

Charles_Varvaya · ‎02-25-2013

Hi Donald,

Thanks for your input. I’ll look into that although I do not think that is it. Here is why I am thinking the way I am: I have a total of one virtual drive. ESXi loads from the same virtual drive that the datastore is stored on. ESXi loads without issue.

Here is my logic:

From the vSphere client, RAID status is: Deassert

From the RAID BIOS status is: Optimal (Healthy)

From the RAID BIOS: All three Drives show as on line.

From the RAID BIOS: There is a total of one Logical Drive of maximum size.

Whereas there is a total of one Logical Drive of maximum size being presented by the RAID controller and whereas EXSi boots, I am comfortable that the RAID healthy.

Thanks again,

Charles Varvayanis

alt="Charles Varvayanis" border=0>Charles Varvayanis

Computer and Communication Systems

P.O. Box 395, Long Barn, CA 95335-0395

Phone: (209) 586-3782 l Fax: (209) 586-3761

charles@varvayanis.com<mailto:charles@varvayanis.com> l www.varvayanis.com<http://www.varvayanis.com/