skipped Error opening Virtual Machine disk

Last post 04-28-2014, 11:35 AM by Mike M.. 13 replies.
Sort Posts: Previous Next
  • skipped Error opening Virtual Machine disk
    Posted: 03-25-2014, 8:55 AM

    I recieve this error as of late daily in one of my Virtual Server Agent setups with VMware ESX 5.0i  914586 and Simpana 9 SP 14. Atleast 1 or 5 may fail out of 118 vm's using a proxy with cluster affinity. I have seen a few threads out here but no resolutions so I am throwing this out there. Given the randomness of the host/vm that fails and the proxy not even being taxed for resources that it might be related to disk latency. The same VM's that fail have been backed up before successfully in previous jobs.

     

    • VMName skipped Error opening Virtual Machine disk(s).  Please ensure that the proxy is able to communicate with the ESX host and resolve the ESX host address.  Also verify that the disks types configured to the virtual machine are supported.

     

    Here is an excerpt from the most recent VSBKP.log

     

     Line 5089: 1464 5f8 03/24 01:19:50 1651633 vsbkp::BackupAllVM() - Processing vmName [watedms01]; vmGuid [4217701c-d3fb-9f90-0727-c301b7cd56b5]
     Line 5095: 1464 a40 03/24 01:19:50 1651633 CVMWareInfo::_MountVM_VCB4() - Mounting VM:[watedms01] with GUID:[4217701c-d3fb-9f90-0727-c301b7cd56b5]
     Line 5096: 1464 a40 03/24 01:19:56 1651633 CVMWareInfo::_MountVM_VCB4() - Mounting VM [watedms01] config [[WAT_WIN_OS11_CX480] watedms01/WATEDMS01.vmx] Moref [vm-11865] hosted by server[watesx60.goodwinprocter.com] version[VMware ESXi 5.0.0 build-914586] and HW version[vmx-08]
     Line 5096: 1464 a40 03/24 01:19:56 1651633 CVMWareInfo::_MountVM_VCB4() - Mounting VM [watedms01] config [[WAT_WIN_OS11_CX480] watedms01/WATEDMS01.vmx] Moref [vm-11865] hosted by server[watesx60.goodwinprocter.com] version[VMware ESXi 5.0.0 build-914586] and HW version[vmx-08]
     Line 5096: 1464 a40 03/24 01:19:56 1651633 CVMWareInfo::_MountVM_VCB4() - Mounting VM [watedms01] config [[WAT_WIN_OS11_CX480] watedms01/WATEDMS01.vmx] Moref [vm-11865] hosted by server[watesx60.goodwinprocter.com] version[VMware ESXi 5.0.0 build-914586] and HW version[vmx-08]
     Line 5097: 1464 a40 03/24 01:19:56 1651633 CVMWareInfo::_MountVM_VCB4() - Change tracking is already enabled on VM [watedms01]
     Line 5098: 1464 a40 03/24 01:19:56 1651633 CVMWareInfo::_MountVM_VCB4() - Datacenter [Watertown] Datastore [WAT_WIN_OS11_CX480] VM Config Dir[watedms01]
     Line 5099: 1464 a40 03/24 01:19:56 1651633 CVMWareInfo::_DownloadConfigFile() - DOWNLOADING VM Config File https://watvmgmt01/folder/watedms01/WATEDMS01.vmx?dcPath=Watertown&dsName=WAT_WIN_OS11_CX480 to C:\Program Files\CommVault\Simpana\iDataAgent\JobResults\CV_JobResults\iDataAgent\VirtualServerAgent\2\2806\(4217701c-d3fb-9f90-0727-c301b7cd56b5)\WATEDMS01.vmx
     Line 5099: 1464 a40 03/24 01:19:56 1651633 CVMWareInfo::_DownloadConfigFile() - DOWNLOADING VM Config File https://watvmgmt01/folder/watedms01/WATEDMS01.vmx?dcPath=Watertown&dsName=WAT_WIN_OS11_CX480 to C:\Program Files\CommVault\Simpana\iDataAgent\JobResults\CV_JobResults\iDataAgent\VirtualServerAgent\2\2806\(4217701c-d3fb-9f90-0727-c301b7cd56b5)\WATEDMS01.vmx
     Line 5099: 1464 a40 03/24 01:19:56 1651633 CVMWareInfo::_DownloadConfigFile() - DOWNLOADING VM Config File https://watvmgmt01/folder/watedms01/WATEDMS01.vmx?dcPath=Watertown&dsName=WAT_WIN_OS11_CX480 to C:\Program Files\CommVault\Simpana\iDataAgent\JobResults\CV_JobResults\iDataAgent\VirtualServerAgent\2\2806\(4217701c-d3fb-9f90-0727-c301b7cd56b5)\WATEDMS01.vmx
     Line 5100: 1464 a40 03/24 01:19:57 1651633 CVMWareInfo::_CreateVMSnapshot() - Creating Snapshot of VM [watedms01] Guid [4217701c-d3fb-9f90-0727-c301b7cd56b5]
     Line 5101: 1464  10 03/24 01:19:57 1651633 ### CreateSnapshot_Task --- Started Create Snapshot task task-178621 for VM watedms01
     Line 5127: 1464  10 03/24 01:20:07 1651633 ### Createsnapshot --- Successfully created Snapshot __GX_BACKUP__ snapshot-42439 from VM watedms01
     Line 5128: 1464 a40 03/24 01:20:07 1651633 CVMWareInfo::_CreateVMSnapshot() - Successfuly created Snapshot [snapshot-42439] of VM [watedms01] Guid [4217701c-d3fb-9f90-0727-c301b7cd56b5]
     Line 5158: 1464  10 03/24 01:20:10 1651633 ### GetVMInfoForVMSnapshot --- Name:watedms01 uuid:4217701c-d3fb-9f90-0727-c301b7cd56b5
     Line 5159: 1464 a40 03/24 01:20:10 1651633 CVMWareInfo::_MountVM_VCB4() - Connecting to VM [watedms01] config [[WAT_WIN_OS11_CX480] watedms01/WATEDMS01.vmx] MoRef [vm-11865] snapshot [snapshot-42439] for disk access
     Line 5159: 1464 a40 03/24 01:20:10 1651633 CVMWareInfo::_MountVM_VCB4() - Connecting to VM [watedms01] config [[WAT_WIN_OS11_CX480] watedms01/WATEDMS01.vmx] MoRef [vm-11865] snapshot [snapshot-42439] for disk access
     Line 5159: 1464 a40 03/24 01:20:10 1651633 CVMWareInfo::_MountVM_VCB4() - Connecting to VM [watedms01] config [[WAT_WIN_OS11_CX480] watedms01/WATEDMS01.vmx] MoRef [vm-11865] snapshot [snapshot-42439] for disk access
     Line 5168: 1464 a40 03/24 01:20:21 1651633 CVMDiskInfo::Connect() - Connected to VM [watedms01] Guid [4217701c-d3fb-9f90-0727-c301b7cd56b5]
     Line 5169: 1464 a40 03/24 01:20:21 1651633 CVMWareInfo::_VerifyChangeTrackingForDisk() - Verifying Change tracking on Disk [WATEDMS01.vmdk]
     Line 5172: 1464 a40 03/24 01:20:24 1651633 CVMWareInfo::_MountVM_VCB4() - Opening Disk [[WAT_WIN_OS11_CX480] watedms01/WATEDMS01.vmdk] as [WATEDMS01.vmdk]
     Line 5172: 1464 a40 03/24 01:20:24 1651633 CVMWareInfo::_MountVM_VCB4() - Opening Disk [[WAT_WIN_OS11_CX480] watedms01/WATEDMS01.vmdk] as [WATEDMS01.vmdk]
     Line 5172: 1464 a40 03/24 01:20:24 1651633 CVMWareInfo::_MountVM_VCB4() - Opening Disk [[WAT_WIN_OS11_CX480] watedms01/WATEDMS01.vmdk] as [WATEDMS01.vmdk]
     Line 5173: 1464 a40 03/24 01:20:24 1651633 CVMDiskInfo::OpenDisk() - Opening disk [WATEDMS01.vmdk] on VM [watedms01] flags [ Readonly ]
     Line 5173: 1464 a40 03/24 01:20:24 1651633 CVMDiskInfo::OpenDisk() - Opening disk [WATEDMS01.vmdk] on VM [watedms01] flags [ Readonly ]
     Line 5186: 1464 a40 03/24 01:21:27 1651633 CVMWareInfo::_MountVM_VCB4() - Failed to Open Disk [[WAT_WIN_OS11_CX480] watedms01/WATEDMS01.vmdk]
     Line 5186: 1464 a40 03/24 01:21:27 1651633 CVMWareInfo::_MountVM_VCB4() - Failed to Open Disk [[WAT_WIN_OS11_CX480] watedms01/WATEDMS01.vmdk]
     Line 5187: 1464 a40 03/24 01:21:27 1651633 CVMWareInfo::_MountVM_VCB4() - Unable to open any disks on VM watedms01 1 attempted
     Line 5189: 1464 a40 03/24 01:21:27 1651633 CVMWareInfo::_UnmountVM_VCB4() - Unmounting Disks for VM [watedms01]
     Line 5195: 1464 a40 03/24 01:21:27 1651633 CVMWareInfo::_RemoveVMSnapshot() - Removing Snapshot [snapshot-42439] of VM [watedms01] Guid [4217701c-d3fb-9f90-0727-c301b7cd56b5]
     Line 5198: 1464  10 03/24 01:21:28 1651633 ### RemoveSnapshot --- Removing Snapshot __GX_BACKUP__ snapshot-42439 from VM watedms01
     Line 5199: 1464  10 03/24 01:21:28 1651633 ### RemoveSnapshot --- Started remove Snapshot task task-178627 for VM watedms01 Snapshot snapshot-42439
     Line 5201: 1464  10 03/24 01:21:35 1651633 ### RemoveSnapshot --- Successfully removed Snapshot __GX_BACKUP__ snapshot-42439 from VM watedms01
     Line 5202: 1464 a40 03/24 01:21:35 1651633 CVMWareInfo::_RemoveVMSnapshot() - Successfuly removed Snapshot of VM [watedms01] Guid [4217701c-d3fb-9f90-0727-c301b7cd56b5]
     Line 5203: 1464 a40 03/24 01:21:35 1651633 vsbkp::CheckVMInfoError() - VM [watedms01] Error opening Virtual Machine disk(s).  Please ensure that the proxy is able to communicate with the ESX host and resolve the ESX host address.  Also verify that the disks types configured to the virtual machine are supported.
     Line 5204: 1464 a40 03/24 01:21:35 1651633 CVMWareInfo::_UnmountVM_VCB4() - Unmounting Disks for VM [watedms01]
     Line 5205: 1464 a40 03/24 01:21:35 1651633 vsbkp::HandleVMComplete() - Skipped VM [watedms01]
     Line 5207: 1464 5f8 03/24 01:21:35 1651633 vsbkp::Wait() - Done processing VM watedms01 - SKIPPED

  • Re: skipped Error opening Virtual Machine disk
    Posted: 03-25-2014, 9:01 AM

    Could you please let me know the CommVault Simpana version 

  • Re: skipped Error opening Virtual Machine disk
    Posted: 03-25-2014, 9:02 AM

    VMware ESX 5.0i  914586 and Simpana 9 SP 14.

  • Re: skipped Error opening Virtual Machine disk
    Posted: 03-25-2014, 9:06 AM

    Also could you please let me know why its failing to open the below disk.

     

     Line 5173: 1464 a40 03/24 01:20:24 1651633 CVMDiskInfo::OpenDisk() - Opening disk [WATEDMS01.vmdk] on VM [watedms01] flags [ Readonly ]
    Line 5186: 1464 a40 03/24 01:21:27 1651633 CVMWareInfo::_MountVM_VCB4() - Failed to Open Disk [[WAT_WIN_OS11_CX480] watedms01/WATEDMS01.vmdk]
    Line 5186: 1464 a40 03/24 01:21:27 1651633 CVMWareInfo::_MountVM_VCB4() - Failed to Open Disk [[WAT_WIN_OS11_CX480] watedms01/WATEDMS01.vmdk]
    Line 5187: 1464 a40 03/24 01:21:27 1651633 CVMWareInfo::_MountVM_VCB4() - Unable to open any disks on VM watedms01 1 attempted
    Line 5189: 1464 a40 03/24 01:21:27 1651633 CVMWareInfo::_UnmountVM_VCB4() - Unmounting Disks for VM [watedms01]
    Line 5195: 1464 a40 03/24 01:21:27 1651633 CVMWareInfo::_RemoveVMSnapshot() - Removing Snapshot [snapshot-42439] of VM [watedms01] Guid [4217701c-d3fb-9f90-0727-c301b7cd56b5]
    Line 5198: 1464 10 03/24 01:21:28 1651633 ### RemoveSnapshot --- Removing Snapshot __GX_BACKUP__ snapshot-42439 from VM watedms01
  • Re: skipped Error opening Virtual Machine disk
    Posted: 03-25-2014, 9:09 AM

    That is the obvious issue and the same for all failures. It is unable to access the disk for some reason temporarily during the job. If I ran the job again it would work. Another reason I suspect some form of IO latency.

  • Re: skipped Error opening Virtual Machine disk
    Posted: 03-27-2014, 9:27 PM
    How many SnapProtect jobs do you have scheduled at the same time? How many streams are you configured to utilize on your subclients? Does this happen on the same disks every time? Is it related to Datastore WAT_WIN_OS11_480 ? Is datastore WAT_WIN_OS11_480 presented correctly?
  • Re: skipped Error opening Virtual Machine disk
    Posted: 03-28-2014, 2:20 PM

    I have played around with 2 - 4 readers in the subclient with the same results.

     

    No, not the same disk or same host or same VM.

     

    All of the datastores have been examined and undergone performance analysys against matching to
    VM, HOST, Datastore, LUN and to raid group were not been taxed for performance in our testing.

     

    6 VM's fail last night. When checking the failed items some say skipped and others skipped with error cannot open disk. 6 seperate VM's left with needs snapshot conolidation.

     

     

     

  • Re: skipped Error opening Virtual Machine disk
    Posted: 03-28-2014, 5:48 PM

    Are any disks being left attached to your VSA proxies instead of being cleaned up automatically?

  • Re: skipped Error opening Virtual Machine disk
    Posted: 03-28-2014, 8:26 PM

    That happened once but it was due to the antivirus on the proxy not allowing it to purge the VM temp files it creates during backup. That has not happened since we excluded all of the folders and processes from scanning.

     

     

  • Re: skipped Error opening Virtual Machine disk
    Posted: 03-30-2014, 1:46 PM

    Checking vixdisklib.log might be helpful here to see what underlying errors are being reported by the VMware VDDK API.  Also, have you tried changing the transport mode being used to see if that makes a difference?  Auto or NBD transport modes might have better luck if you are currently forcing the use of HotAdd or SAN transport modes.

  • Re: skipped Error opening Virtual Machine disk
    Posted: 03-31-2014, 3:05 PM

    So, I had the transport mode set to auto and just recently changed it to hotadd. In turn, the vixdisklib.log shows NBD failures for some VM's and others using hotadd just fine in the same VM cluster. I am setting the transport mode back to auto but was wondering why any VM would require NBD in the same cluster as the proxy.

  • Re: skipped Error opening Virtual Machine disk
    Posted: 04-01-2014, 1:58 PM

    Do the disks which fail to hot add fail when trying to mount many VMDKs to the same VSA proxy(many as in >~7)?  Sometimes the VSA proxy can run out of SCSI addresses if it only has a single SCSI adapter.  You need a free SCSI address to hotadd a disk.  This is easy to fix by adding additional SCSI controllers to the VSA proxies.

    There are also some VMware restrictions around using HotAdd transport if the disk being hotadded resides on a datastore that is a different version of VMFS or has a different block size than the datastore on which the VSA proxy resides (this doesn't apply if your datastores are all VMFS-5 since the block size is always 1MB).  Neither of these are common but they are worth checking.  There is also a VMware bug if a VMDK of a Windows VM which is being hotadded is larger than 2 TB and you are using application-consistent quiescing.

    A full set of logs or opening a TR would be good next steps for investigating this issue.

  • Re: skipped Error opening Virtual Machine disk
    Posted: 04-03-2014, 1:05 PM

    Are their logs I could peruse that would confirm that I am having an issue with the scsi limit on the proxy?

     

    as far as the hotadd restriction, yes I have 2 datastores that are using VMFS 3 out of the 30 associated to the cluster so I guess those default to NBD as a result. I increased the management vswitch to account for throughput. It was previoulsy 500 MB. The proxy is 4 GB.

     

    The issue we see with the skipped VM's is when there is an error with snapshot removal on the host and the host begins to not respond disconnecting from the vcenter the consolidation completes but is skipped in the VM job.

     

    I believe this could be more about VSA management of the job. Even if you set the readers to 2 or 3 you cannot tell the VSA agent to not perform more then 1 backup per ESX host at any time. So I see that the same host is cleaning up snapshots 2 or 3 at a time since I have it set to 3 readers to get through 120 VM's before business starts.

    Are there any reg keys or anything that would allow me to enforce a rule to limit VM backups per host?

     

     

     

     

     

  • Re: skipped Error opening Virtual Machine disk
    Posted: 04-28-2014, 11:35 AM

    So, here is the resolution which I recieved from VMware support.

    ESXi 5.0 Update 3.

    After installing the update on all of the ESXi hosts in the cluster and removing and re-installing the VMtools on the proxy Media Agent all of the issues I was having went away.

    If you installed the Update 3 VDDk prior on the proxy media agent then you must first remove it and then delete the install path in the registery before re-installing VMtools.  

     

     

The content of the forums, threads and posts reflects the thoughts and opinions of each author, and does not represent the thoughts, opinions, plans or strategies of Commvault Systems, Inc. ("Commvault") and Commvault undertakes no obligation to update, correct or modify any statements made in this forum. Any and all third party links, statements, comments, or feedback posted to, or otherwise provided by this forum, thread or post are not affiliated with, nor endorsed by, Commvault.
Commvault, Commvault and logo, the “CV” logo, Commvault Systems, Solving Forward, SIM, Singular Information Management, Simpana, Commvault Galaxy, Unified Data Management, QiNetix, Quick Recovery, QR, CommNet, GridStor, Vault Tracker, InnerVault, QuickSnap, QSnap, Recovery Director, CommServe, CommCell, SnapProtect, ROMS, and CommValue, are trademarks or registered trademarks of Commvault Systems, Inc. All other third party brands, products, service names, trademarks, or registered service marks are the property of and used to identify the products or services of their respective owners. All specifications are subject to change without notice.
Close
Copyright © 2018 Commvault | All Rights Reserved. | Legal | Privacy Policy