VSAN for VSphere Installation Issues

[DarkDiamond]

Hello,

First I'd like to say thank you for providing a free high availability option for vSphere users with no size restrictions

Now onto my questions... I'm following your PDF on configuring my two host ESXi cluster (http://www.starwindsoftware.com/starwin ... re-vsphere). I'm having difficulties configuring the loopback interface so I can mount LUNS on the host that is also hosting the SAN VM. I was able to successfully create the vSwitch as per Step 3 on page 14 as well as the vmkernel to enable iSCSI on that vSwitch. I added a network interface to the Starwind VM which is attached to the same vSwitch. I was able to ping the SAN target but vSphere would never see any of the devices I created on the SAN VM. The only way I was able to mount them was to attach the Starwind VM network adapter and the ISCSI vmkernel to a vSwitch that had a vmnic attached to it. Once I did that I was able to see the LUNs and created datastores, etc. Following is an excerpt of the Starwind logs that I saw every time I would kick off a rescan.

10/26 8:45:48.624 474 C[11], XPT_UP: Event - LOGIN.
10/26 8:45:48.624 474 C[11], IN_LOGIN: T4.
10/26 8:45:48.624 474 Params: <<< String param 'InitiatorName': received 'iqn.2012-06.com.cedarwoodtechsolutions:esx2', accepted 'iqn.2012-06.com.cedarwoodtechsolutions:esx2'
10/26 8:45:48.624 474 Params: <<< Enum param 'SessionType': received 'Discovery', accepted 'Discovery'
10/26 8:45:48.624 474 Params: <<< Enum param 'HeaderDigest': received 'None', accepted 'None'
10/26 8:45:48.624 474 Params: <<< Enum param 'DataDigest': received 'None', accepted 'None'
10/26 8:45:48.624 474 Params: <<< Numeric param 'DefaultTime2Wait': received 0, accepted 0
10/26 8:45:48.624 474 Params: <<< Numeric param 'DefaultTime2Retain': received 0, accepted 0
10/26 8:45:48.624 474 Params: <<< Boolean param 'IFMarker': received No, accepted 0
10/26 8:45:48.624 474 Params: <<< Boolean param 'OFMarker': received No, accepted 0
10/26 8:45:48.624 474 Params: <<< Numeric param 'ErrorRecoveryLevel': received 0, accepted 0
10/26 8:45:48.624 474 Params: <<< Numeric param 'MaxRecvDataSegmentLength': received 32768, accepted 32768
10/26 8:45:48.624 474 Params: >>> ErrorRecoveryLevel=0.
10/26 8:45:48.624 474 Params: >>> HeaderDigest=None.
10/26 8:45:48.624 474 Params: >>> DataDigest=None.
10/26 8:45:48.624 474 Params: >>> OFMarker=No.
10/26 8:45:48.624 474 Params: >>> IFMarker=No.
10/26 8:45:48.624 474 Params: >>> InitialR2T=No.
10/26 8:45:48.624 474 Params: >>> ImmediateData=Yes.
10/26 8:45:48.624 474 Params: >>> MaxRecvDataSegmentLength=262144.
10/26 8:45:48.624 474 Params: >>> MaxBurstLength=262144.
10/26 8:45:48.624 474 Params: >>> FirstBurstLength=262144.
10/26 8:45:48.624 474 Params: >>> DefaultTime2Wait=0.
10/26 8:45:48.624 474 Params: >>> DefaultTime2Retain=0.
10/26 8:45:48.624 474 Params: >>> MaxOutstandingR2T=1.
10/26 8:45:48.624 474 Params: >>> DataPDUInOrder=Yes.
10/26 8:45:48.624 474 Params: >>> DataSequenceInOrder=Yes.
10/26 8:45:48.624 12c T[11,1]: session 0x11, connection 0x11 : end of stage 1, next stage 3.
10/26 8:45:48.624 12c C[11], IN_LOGIN: Event - LOGIN_ACCEPT.
10/26 8:45:48.624 12c C[11], LIN: T5.
10/26 8:45:48.624 474 error: assertion failed: c:\_starwind\_release_8_0_r2\starwind\service\server\task.cpp:3462 (m_readData.size() == 0)
10/26 8:45:48.624 474 error: assertion failed: c:\_starwind\_release_8_0_r2\starwind\service\server\task.cpp:3470 (m_readData.size() == 0)
10/26 8:45:48.624 474 Srv: <no target>: 'SendTargets=All' for a Discovery session...
10/26 8:45:48.624 12c C[11], LIN: Event - LOGOUT.
10/26 8:45:48.624 12c C[11], IN_LOGOUT: T9/10.
10/26 8:45:48.624 404 C[11], IN_LOGOUT: Event - LOGOUT_ACCEPT.
10/26 8:45:48.624 404 C[11], FREE: T13.
10/26 8:45:48.624 474 C[11], FREE: recvData returned 10054


Onto the second issue: I created datastores and cloned two VMs to the new datastore. That went fine. I then started to copy files to the new VM. After about half way through, the file copy froze along with the VM. I was never able to recover it. Eventually my VM got corrupted. It is no longer visible in the datastore browser. The name of the VM became "/vmfs/volumes/544cf7d2-cfe144ad-9398-00151763a4bc/Files/Files.vmx" instead of simply, Files. Following is an excerpt of the Starwind logs when this corruption happened. These logs appear quite a lot in the file at the time the file copy was happening.

10/26 12:36:22.895 4c C[4], LIN: T5.
10/26 12:36:59.113 53c T[4,8]: Management command: abort task (CmdSN 72025, ITT 0x1a1a0100) not found.
10/26 12:37:00.004 53c T[4,b]: Management command: abort task (CmdSN 72026, ITT 0x1b1a0100) not found.
10/26 12:37:00.004 a74 IMG: *** ImageFile_IoCompleted: Error (1117) returned to IO completion!
10/26 12:37:00.004 a74 IMG: *** ImageFile_ReadWriteSectorsCompleted: Error occured (ScsiStatus = 2, DataTransferLength = 0)!
10/26 12:37:00.004 a7c IMG: *** ImageFile_IoCompleted: Error (1117) returned to IO completion!
10/26 12:37:00.004 a7c IMG: *** ImageFile_ReadWriteSectorsCompleted: Error occured (ScsiStatus = 2, DataTransferLength = 0)!
10/26 12:37:00.004 a7c IMG: *** ImageFile_IoCompleted: Error (1117) returned to IO completion!
10/26 12:37:00.004 a7c IMG: *** ImageFile_ReadWriteSectorsCompleted: Error occured (ScsiStatus = 2, DataTransferLength = 0)!
10/26 12:37:00.004 a74 IMG: *** ImageFile_IoCompleted: Error (1117) returned to IO completion!
10/26 12:37:00.004 a74 IMG: *** ImageFile_ReadWriteSectorsCompleted: Error occured (ScsiStatus = 2, DataTransferLength = 0)!
10/26 12:37:01.566 a7c IMG: *** ImageFile_ReadWriteSectorsCompleted: Error occured (ScsiStatus = 2, DataTransferLength = 0)!
10/26 12:37:01.566 a7c IMG: *** ImageFile_ReadWriteWithCacheCompleted: Error (0xC0000001) returned to cache request completion!
10/26 12:37:01.566 a7c IMG: *** ImageFile_IoCompleted: Error (1117) returned to IO completion!
10/26 13:07:13.301 a74 IMG: *** ImageFile_IoCompleted: Error (1117) returned to IO completion!
10/26 13:07:13.301 a74 IMG: *** ImageFile_ReadWriteSectorsCompleted: Error occured (ScsiStatus = 2, DataTransferLength = 0)!
10/26 13:07:13.301 a74 IMG: *** ImageFile_ReadWriteWithCacheCompleted: Error (0xC0000001) returned to cache request completion!

Some additional notes to keep in mind. I have not configured high availability as I need to migrate my VMs off of disks so I can repurpose them and add them to my other host. So for right now, this is just a hyperconverged single node iSCSI VM. I have write back cache configured on the LUN as well since I wanted to be prepared for when I bring the second node online.

I am running the latest version of Starwind (8.0.7145).

I would really appreciate any help you can provide.

Thanks

[DarkDiamond]

Just wanted to provide an update...

Since I didn't hear any responses I decided to reinstall the most recent ESXi build on the host I've been experimenting with. I only performed the most basic of configurations on the host, enough to get one management NIC working, followed by the local iscsi traffic vSwitch as per Step 3 as well as the iscsi vmkernel on that vSwitch. I was able to mount a LUN successfully, which is further than I got the first time I tried. I used the E1000E adapter.

I ran CrystalDiskMark several times on the SAN VM to make sure I wasn't having any performance issues with the underlying raid array. Performance is fine.

After I mounted the LUN, I created a new Win 2012 R2 VM. Performance was horrible. I removed the NICS from the SAN VM, readded them as VMXNET 3 and rebooted. Performance was much, much better. Once the test VM completed the initial installation, it rebooted itself and began to configure the operating system and install the necessary drivers. At this point the VM locked up, then the LUN got corrupted and unmounted itself. The device stayed visible within ESXi but the datastore itself dropped off the list. When I tried to add storage, Vsphere wanted me to reformat the datastore. The LUN itself within Starwind was configured as a 40GB image disk with 512K of write back cache. The VM was set up per the document, 4CPU and 4GB of RAM.

These are some of the errors I see in the Starwind log:


10/28 19:29:03.747 9f8 Srv: Worker: GetQueuedCompletionStatus() failed (error 1117)!
10/28 19:29:03.747 9f8 IMG: *** ImageFile_IoCompleted: Error (1117) returned to IO completion!
10/28 19:29:03.747 9f8 IMG: *** ImageFile_ReadWriteSectorsCompleted: Error occured (ScsiStatus = 2, DataTransferLength = 0)!
10/28 19:29:09.969 b3c T[2,7]: Management command: abort task (CmdSN 514896, ITT 0x89db0700) not found.
10/28 19:29:09.969 9f8 IMG: *** ImageFile_ScsiExec: Deferred error reported for session id 5.
10/28 19:29:12.971 9f8 IMG: *** ImageFile_IoCompleted: Error (1117) returned to IO completion!
10/28 19:29:13.080 9f8 IMG: *** ImageFile_ReadWriteWithCacheCompleted: Error (0xC0000001) returned to cache request completion!
10/28 19:29:13.252 9f8 IMG: *** ImageFile_ReadWriteSectorsCompleted: Error occured (ScsiStatus = 2, DataTransferLength = 0)!
10/28 19:29:15.910 a24 PR: [pr] LUN 0, scsiop 0x0: session 0x1 is not registered!
10/28 19:29:15.910 a24 PR: [pr] LUN 0, scsiop 0x89: session 0x1 is not registered!
10/28 19:29:15.910 a24 PR: [pr] LUN 0, scsiop 0x28: session 0x1 is not registered!
10/28 19:29:15.910 b3c C[2], LIN: recvData returned 10058
10/28 19:29:15.910 b3c C[2], LIN: *** 'recv' thread: recv failed 10058.
10/28 19:29:15.910 b58 Tgt: close 'iqn.2012-06.com.cedarwoodtechsolutions:san2-target': 0 session(s) opened, 65536 more allowed.
10/28 19:29:15.910 9f8 IMG: *** ImageFile_IoCompleted: Error (1117) returned to IO completion!
10/28 19:29:15.910 9f8 IMG: *** ImageFile_ReadWriteSectorsCompleted: Error occured (ScsiStatus = 2, DataTransferLength = 0)!
10/28 19:29:15.957 9f8 IMG: *** ImageFile_IoCompleted: Error (1117) returned to IO completion!
10/28 19:29:15.957 9f8 IMG: *** ImageFile_ReadWriteSectorsCompleted: Error occured (ScsiStatus = 2, DataTransferLength = 0)!
10/28 19:29:15.957 9f8 IMG: *** ImageFile_ReadWriteWithCacheCompleted: Error (0xC0000001) returned to cache request completion!
10/28 19:29:18.943 9e4 Srv: Accepted iSCSI connection from 192.168.10.11:61859 to 192.168.10.1:3260. (Id = 0x3)
10/28 19:29:35.061 9f8 IMG: *** ImageFile_ReadWriteSectorsCompleted: Error occured (ScsiStatus = 2, DataTransferLength = 0)!
10/28 19:29:35.061 9f8 IMG: *** ImageFile_ReadWriteWithCacheCompleted: Error (0xC0000001) returned to cache request completion!
10/28 19:29:35.061 9a0 SCSI: VAAI C&W: READ (0x28) returned CHECK CONDITION (3/0/0)!
10/28 19:29:35.061 9f8 IMG: *** ImageFile_IoCompleted: Error (1117) returned to IO completion!
10/28 19:29:35.061 9f8 IMG: *** ImageFile_ReadWriteSectorsCompleted: Error occured (ScsiStatus = 2, DataTransferLength = 0)!
10/28 19:29:35.061 9f8 IMG: *** ImageFile_ReadWriteWithCacheCompleted: Error (0xC0000001) returned to cache request completion!
10/28 19:29:35.061 9a0 SCSI: VAAI C&W: READ (0x28) returned CHECK CONDITION (3/0/0)!
10/28 19:29:35.452 9f8 IMG: *** ImageFile_IoCompleted: Error (1117) returned to IO completion!


Throughout all of this, the SAN VM stayed responsive and online (I know because I was looking at the console and clicking to see the logs and Starwind performance information). To me, this rules out my raid array as the culprit. To me, the issue seems to be within Starwind itself. I'm happy to supply you with the entire log if it would help and I'm happy to try any suggestions. Otherwise, I'm going to scrap this entire effort as I cannot trust my data to not become corrupted.

Thanks,
Chris

[anton (staff)]

There was a bug in VAAI implementation, we now aware of it and we had fixed it some time ago. R&D will provide you with a private link for experimental build we'll merge with an upcoming StarWind update. Thank you!

[Alex (staff)]

I've sent the link to the pre-release build with PM.

[DarkDiamond]

Thank you so much. I will try it as soon as I can.

Anton mentioned this fix was for a VAAI bug. I wasn't doing any cloning or vMotion'ing of VMs. It was a fresh VM installation.

Do you know when this will be made available as an official release?

I've sent the link to the pre-release build with PM.

[Alex (staff)]

I see a fragment of processing VAAI COMPARE AND WRITE command in your log.

This build will be published at the start of the next week.

[DarkDiamond]

Probably from the allocation of new blocks since the test VM was a thin provisioned disk. Looking forward to trying this

Thank you again.

I see a fragment of processing VAAI COMPARE AND WRITE command in you log.

This build will be published at the start of the next week.

[DarkDiamond]

I tried the new build and unfortunately it didn't work out. These are more snippets from the log. I saw the same behavior.

10/29 12:29:26.535 a44 Srv: Worker: GetQueuedCompletionStatus() failed (error 1117)!
10/29 12:29:26.535 a44 IMG: *** ImageFile_IoCompleted: Error (1117) returned to IO completion!
10/29 12:29:26.535 a44 IMG: *** ImageFile_ReadWriteSectorsCompleted: Error occured (ScsiStatus = 2, DataTransferLength = 0)!
10/29 12:29:33.444 4c8 T[2,7]: Management command: abort task (CmdSN 782581, ITT 0x6dff0b00) not found.
10/29 12:29:33.444 9c8 IMG: *** ImageFile_ScsiExec: Deferred error reported for session id 5.
10/29 12:29:36.460 a44 IMG: *** ImageFile_IoCompleted: Error (1117) returned to IO completion!
10/29 12:29:36.460 a44 IMG: *** ImageFile_ReadWriteSectorsCompleted: Error occured (ScsiStatus = 2, DataTransferLength = 0)!
10/29 12:29:38.976 a44 IMG: *** ImageFile_ReadWriteSectorsCompleted: Error occured (ScsiStatus = 2, DataTransferLength = 0)!
10/29 12:29:38.976 a70 PR: [pr] LUN 0, scsiop 0x0: session 0x1 is not registered!
10/29 12:29:38.976 a70 IMG: *** ImageFile_ScsiExec: Deferred error reported for session id 3.
10/29 12:29:38.976 a70 PR: [pr] LUN 0, scsiop 0x89: session 0x1 is not registered!
10/29 12:29:38.976 a44 IMG: *** ImageFile_IoCompleted: Error (1117) returned to IO completion!
10/29 12:29:38.992 a70 PR: session 1 not found.
10/29 12:29:38.992 a70 Tgt: close 'iqn.2012-06.com.cedarwoodtechsolutions:san2-target': 1 session(s) opened, 65535 more allowed.
10/29 12:29:38.992 a70 S[1]: ~Session
10/29 12:29:38.992 a44 IMG: *** ImageFile_IoCompleted: Error (1117) returned to IO completion!
10/29 12:29:38.992 a44 IMG: *** ImageFile_ReadWriteSectorsCompleted: Error occured (ScsiStatus = 2, DataTransferLength = 0)!
10/29 12:29:38.992 4c8 C[2], LIN: recvData returned 10058
10/29 12:29:38.992 4c8 C[2], LIN: *** 'recv' thread: recv failed 10058.
10/29 12:29:38.992 9c8 Tgt: close 'iqn.2012-06.com.cedarwoodtechsolutions:san2-target': 0 session(s) opened, 65536 more allowed.
10/29 12:29:38.992 9c8 S[2]: ~Session
10/29 12:30:51.153 a44 IMG: *** ImageFile_ReadWriteSectorsCompleted: Error occured (ScsiStatus = 2, DataTransferLength = 0)!
10/29 12:30:51.153 a44 IMG: *** ImageFile_ReadWriteWithCacheCompleted: Error (0xC0000001) returned to cache request completion!
10/29 12:30:51.153 a44 IMG: *** ImageFile_IoCompleted: Error (1117) returned to IO completion!
10/29 12:30:51.153 a44 IMG: *** ImageFile_ReadWriteSectorsCompleted: Error occured (ScsiStatus = 2, DataTransferLength = 0)!
10/29 12:30:51.153 a44 IMG: *** ImageFile_ReadWriteWithCacheCompleted: Error (0xC0000001) returned to cache request completion!

The "ImageFile_ReadWriteSectorsCompleted" are repeated many times throughout the log.

Probably from the allocation of new blocks since the test VM was a thin provisioned disk. Looking forward to trying this

Thank you again.

I see a fragment of processing VAAI COMPARE AND WRITE command in you log.

This build will be published at the start of the next week.

[DarkDiamond]

Additional information:

I noticed a few errors in the Event Log of the SAN VM in addition to the Starwind logs.

At the time that I received this error in the Starwind log (Srv: Worker: GetQueuedCompletionStatus() failed (error 1117)!) at 15:43, I saw this error in the system event log: (source: pvscsi, message: reset to device \device\raidport0 was issued). The VM locked up at that time.

I also saw this earlier... source: disk, message was, "The IO operation at logical block address 000 for Disk 1 (PDO name: \device\00000038) was retried.

As soon as I saw those errors, the VM I was creating using the iSCSI local loopback interface went unresponsive.

Please keep in mind those disk IO errors were received on the Starwind iSCSI VM. No errors were logged to the RAID array itself when I look at it through Vsphere management console. Earlier today I had used the default LSI controller to attach the disks to the VM. When I saw those errors I looked them up online and the KB from VMWare recommended I change to VMware's paravirtualized controller. I deleted my Starwind VM, rebuilt it using the pvscsi adapter and got the same corruption results.

Please let me know what I can troubleshoot as I'm pretty much out of ideas at this point.

Thanks,
Chris

[Alex (staff)]

Could you please send full log file which contains the error to support@starwindsoftware.com?

[DarkDiamond]

Sure. I just sent them to your support email address.

I have a little more information... not sure if it helps...

I tried creating a new SAN VM using Windows Server 2008 R2 to see if it had the same behavior. When I created my test VM on a LUN exposed by the 2008 R2 SAN VM, it didn't corrupt like it does on Win 2012. As I was starting a file copy, I opened up the resource monitor and looked at my disk queue length and usage times on the SAN VM. I noticed periods of time where the disk usage time would shoot to 100% and stay there while the rate of transfer to my disk would fall to 0. Almost like the D drive would freeze. For reference, the D drive is where my iSCSI img files are located. They are on the same array as the C drive, which stays responsive throughout the freeze. I also observed my latency for the array itself spike a few times to 100ms.

I have been monitoring my raid controller logs throughout all of this (LSI 9260-4i) and have not seen any error messages. I was able to copy files to the raw storage datastore (where my SAN VM located) while the SAN VM D drive was frozen. The raid array is backed by a battery which comes out working fine in diagnostics. Write back caching is turned on for the raid array. I'm going to kick off a consistency check to be sure there isn't any issues.

I know this may be information overload - but I hope it helps.

Is there any further diagnostics or anything else I can try that may help?

Thanks,
Chris

[Alex (staff)]

Thank you for new information! We need to examine the logs and will try to reproduce these problems in our lab. I'll get back here with updates and new questions in two-three days.

[DarkDiamond]

Thank you so much for looking into this further

Good luck,
Chris

[DarkDiamond]

One last piece of information...

The SAN VM C and D drives were both configured at thick-provisioned, lazy zeroed.
The test VM I created was configured as thin-provisioned.

Chris

[Anatoly (staff)]

Hello everyone!
just want to give you guys an head up and let know that we uploaded the new build to the website, so you are very welcomed to try it out.