gotts
Enthusiast
Enthusiast

Error with IP Customization using the CSV method

Jump to solution

This error is similar to the OS Heartbeat error that has been well documented here but I can't find anything specific to the IP Address customization timing out which is my problem.

I had this working yesterday then I applied the latest and greatest patches to my ESX servers today and now the recovery test consistently gets to about 50 or 60 % of the Change Network step then times out. I have extended the timeout to 1000 and it does not help. When the step times out the test errors out. If I manually remove the customization step from the vm's the recovery completes without issue.

Does anyone know what patch might be at fault or if there is some other potential cause for this problem? I am running VC 2.5 build 104215 and ESX 3.02 Build 95415 with just about every available patch installed.

0 Kudos
1 Solution

Accepted Solutions
Smoggy
VMware Employee
VMware Employee

what OS version are the VM's your trying to recover???

your guest customization log suggests that the sysprep version being used is Windows 2000 Sysprep (Sysprep version 5.00.2195.2104).

if your VM's being recovered in the recovery plan are NOT Windows 2000 then guest customization is going to fail. If this is the case then it sounds like your VC server at the recovery site does not have access to the necessary sysprep files for all of the Windows versions you are using.

You obtain sysprep from microsoft, for most windows builds you can extract them from the deploy.cab file located in the deployment tools folder on the OS media CD/DVD. Once you have the necessary deploy.cab for the version of windows you wish to customize in virtualcenter you must extract the contents of the.cab file to the correct location on your virtualcenter server.

If you login to the recovery site virtualcenter server navigate to this folder: C:\Documents and Settings\All Users\Application Data\VMware\VMware VirtualCenter\sysprep under here you will see the subfolder "stubs" for the various windows builds. initially these subfolders will be empty until you download/locate the deploy.cab files that match the OS version for that sub folder and then extract the contents into this folder.

this webpage has some info and links for the major versions:

http://www.vm-help.com/esx/other/sysprep_download_links.html

I would suggest, based on the errors that you first check the version of windows your recovering that hangs on "change network settings" and then verify that on the recovery site VC server you have the necessary sysprep files located in the C:\Documents and Settings\All Users\Application Data\VMware\VMware VirtualCenter\sysprep\<youOStype> folder.

hope this helps,

Lee Dilworth

View solution in original post

0 Kudos
12 Replies
admin
Immortal
Immortal

Any chance you could post the relevant sections of the server logs?

0 Kudos
MatthewCEvans
Contributor
Contributor

Does this appear to be consistently happening with all of your servers? I just started looking into the same problem for another client and I'm seeing inconsistent results where it sometimes works and sometimes doesn't. Hopefully have more details on it tomorrow.

Matthew Evans

Kraft & Kennedy, Inc.

360 Lexington Ave.

New York, NY 10017

Direct: 212.692.5608

email: evans@kraftkennedy.com

Matthew Evans Kraft & Kennedy, Inc. 360 Lexington Ave. New York, NY 10017 Direct: 212.692.5608 email: evans@kraftkennedy.com
0 Kudos
Smoggy
VMware Employee
VMware Employee

Hi

As others have said first be good to see:

- SRM log (after failure) from recovery site SRM server

- VM guest customsation log from VM being recovered that fails.

When using ip customization on a VM when you see the recovery plan hit "change network settings" then one thing you can do is switch to the hosts and clusters view in vc locate your VM being recovered and open a console to it.

At this point you will be able to sit and watch the console for the VM and observe guest customization taking place. As with any guest customization you will see a dos window appear in the console which contains the state of the task and also details location being used to write the guest customization log files. Basically watch the window for errors and then review the logs within the VM that customsation produces.This will show you which step in that customization job is timing out. At same time also check status of vmtools within the VM.

Let us know how it goes and post the info mentioned above both SRM and guest logs.

Lee Dilworth

0 Kudos
gotts
Enthusiast
Enthusiast

I would be more than happy to post the logs if someone could provide a little insight on where to find them. I am not that strong at troubleshooting just yet. Also the issue is occurring on all of my protected VM's if that helps answer your question.

0 Kudos
gotts
Enthusiast
Enthusiast
From my most recent test. Did not get as far this time.
[2009-03-12 08:42:43.046 'SecondaryReplication' 2812 verbose] Changing recovery state of 'shadow-group-4245' to 'startingTest'
[2009-03-12 08:42:43.046 'SecondaryReplication' 2812 verbose] Saving ShadowGroup to DB object
[2009-03-12 08:42:43.046 'SecondarySanProvider' 2808 verbose] Found 2 VirtualMachines in group 'shadow-group-4245' of 2 ShadowVms
[2009-03-12 08:42:43.062 'SecondarySanProvider' 2808 trivia] Found 1 properties for object 'vim.HostSystem:host-594'
[2009-03-12 08:42:43.062 'SecondarySanProvider' 2808 trivia] Found 1 properties for object 'vim.HostSystem:host-559'
[2009-03-12 08:42:43.062 'SecondarySanProvider' 2808 verbose] Found 2 hosts for 2 VMs
[2009-03-12 08:42:43.169 'RecoveryContext-70-Task' 2636 verbose] GetState returned running
[2009-03-12 08:42:43.169 'RSStorageOperation-10555-Task' 2812 verbose] Task created
[2009-03-12 08:42:43.185 'RSStorageOperationList-10554-Task' 2812 info] Starting Task RSStorageOperation-10555-75 for step RSStorageOperation-10555
[2009-03-12 08:42:43.185 'RSStorageOperationList-10554-Task' 2812 verbose] MultipleRecoveryTask Info max 1 cur 1 remain 0
[2009-03-12 08:42:43.185 'RSStorageOperation-10555-Task' 2812 info] State set to running
[2009-03-12 08:42:43.185 'RSStorageOperation-10555-Task' 2812 verbose] Scheduling work item
[2009-03-12 08:42:43.185 'RSStorageOperationList-10554-Task' 2796 info] MRT-Progress Task RSStorageOperation-10555-75 for dr.secondary.RecoveryStep:RSStorageOperation-10555 0
[2009-03-12 08:42:43.185 'RSStorageOperationList-10554-Task' 2796 verbose] Progress is unchanged
[2009-03-12 08:42:43.185 'RSStorageOperation-10555-Task' 2796 info] Running work method
[2009-03-12 08:42:43.185 'RSStorageOperation-10555' 2796 info] SetRuntimeStatus for RSStorageOperation-10555 from queued to running
[2009-03-12 08:42:43.185 'RSStorageOperationList-10554-Task' 2812 info] Not Starting Tasks MaxNumRunningTasks
[2009-03-12 08:42:43.185 'RSStorageOperationList-10554-Task' 2812 info] Work function yielded
[2009-03-12 08:42:43.584 'SecondarySanProvider' 2808 verbose] Creating lun snapshots for group 'SRM_FP_OS'
[2009-03-12 08:42:43.584 'SecondarySanProvider' 2808 info] Command Line for testFailover: "E:\Program Files\VMware\VMware Site Recovery Manager\external\perl-5.8.8\bin\perl.exe" "E:/Program Files/VMware/VMware Site Recovery Manager/scripts/SAN/LeftHand Networks/command.pl"
[2009-03-12 08:42:43.584 'SecondarySanProvider' 2808 verbose] Input for testFailover: <?xml version="1.0" encoding="UTF-8"?>
[#2] <Command>
[#2]   <Name>testFailover</Name>
[#2]   <ConnectSpec>
[#2]     <Name>SAN/iQ</Name>
[#2]     <Address>10.19.49.64</Address>
[#2]     <Address>10.19.49.62</Address>
[#2]     <Username>gotts</Username>
[#2]     <Password>********</Password>
[#2]   </ConnectSpec>
[#2]   <Action>start</Action>
[#2]   <ArrayId>SRM_FP;2866F8D055E8E47D48C3F8BBC5C2BAE3</ArrayId>
[#2]   <InitiatorGroupList>
[#2]     <InitiatorGroup id="iScsi-fc-all">
[#2]       <Initiator id="iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d" type="iscsi"/>
[#2]       <Initiator id="iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07" type="iscsi"/>
[#2]     </InitiatorGroup>
[#2]   </InitiatorGroupList>
[#2]   <LunAccess>
[#2]     <ReplicaLun key="007C420D5785E225AE6F82584BC73585;SRM_LV;30;SRM_LV_Sch_RS_1_Pri">
[#2]       <InitiatorGroup id="iScsi-fc-all"/>
[#2]     </ReplicaLun>
[#2]   </LunAccess>
[#2]   <ReplicaLunKeyList>
[#2]     <ReplicaLunKey>007C420D5785E225AE6F82584BC73585;SRM_LV;30;SRM_LV_Sch_RS_1_Pri</ReplicaLunKey>
[#2]   </ReplicaLunKeyList>
[#2]   <SplitReplication>false</SplitReplication>
[#2]   <OutputFile>C:\WINDOWS\TEMP\vmware-SYSTEM\dr-sanprovider0</OutputFile>
[#2]   <LogLevel>trivia</LogLevel>
[#2] </Command>
[2009-03-12 08:42:43.584 'SecondarySanProvider' 2808 trivia] Environment ALLUSERSPROFILE=C:\Documents and Settings\All Users will be set for the script
[2009-03-12 08:42:43.584 'SecondarySanProvider' 2808 trivia] Environment ClusterLog=C:\WINDOWS\Cluster\cluster.log will be set for the script
[2009-03-12 08:42:43.584 'SecondarySanProvider' 2808 trivia] Environment CommonProgramFiles=C:\Program Files\Common Files will be set for the script
[2009-03-12 08:42:43.584 'SecondarySanProvider' 2808 trivia] Environment COMPUTERNAME=RSFP2K3VC25 will be set for the script
[2009-03-12 08:42:43.584 'SecondarySanProvider' 2808 trivia] Environment ComSpec=C:\WINDOWS\system32\cmd.exe will be set for the script
[2009-03-12 08:42:43.584 'SecondarySanProvider' 2808 trivia] Environment DEFLOGDIR=C:\Documents and Settings\All Users\Application Data\McAfee\DesktopProtection will be set for the script
[2009-03-12 08:42:43.584 'SecondarySanProvider' 2808 trivia] Environment FP_NO_HOST_CHECK=NO will be set for the script
[2009-03-12 08:42:43.584 'SecondarySanProvider' 2808 trivia] Environment NUMBER_OF_PROCESSORS=1 will be set for the script
[2009-03-12 08:42:43.584 'SecondarySanProvider' 2808 trivia] Environment OS=Windows_NT will be set for the script
[2009-03-12 08:42:43.584 'SecondarySanProvider' 2808 trivia] Environment Path=C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\Program Files\Microsoft SQL Server\90\Tools\binn\ will be set for the script
[2009-03-12 08:42:43.584 'SecondarySanProvider' 2808 trivia] Environment PATHEXT=.COM;.EXE;.BAT;.CMD;.VBS;.VBE;.JS;.JSE;.WSF;.WSH will be set for the script
[2009-03-12 08:42:43.584 'SecondarySanProvider' 2808 trivia] Environment PROCESSOR_ARCHITECTURE=x86 will be set for the script
[2009-03-12 08:42:43.584 'SecondarySanProvider' 2808 trivia] Environment PROCESSOR_IDENTIFIER=x86 Family 16 Model 2 Stepping 3, AuthenticAMD will be set for the script
[2009-03-12 08:42:43.584 'SecondarySanProvider' 2808 trivia] Environment PROCESSOR_LEVEL=16 will be set for the script
[2009-03-12 08:42:43.584 'SecondarySanProvider' 2808 trivia] Environment PROCESSOR_REVISION=0203 will be set for the script
[2009-03-12 08:42:43.584 'SecondarySanProvider' 2808 trivia] Environment ProgramFiles=C:\Program Files will be set for the script
[2009-03-12 08:42:43.584 'SecondarySanProvider' 2808 trivia] Environment SystemDrive=C: will be set for the script
[2009-03-12 08:42:43.584 'SecondarySanProvider' 2808 trivia] Environment SystemRoot=C:\WINDOWS will be set for the script
[2009-03-12 08:42:43.584 'SecondarySanProvider' 2808 trivia] Environment TEMP=C:\WINDOWS\TEMP will be set for the script
[2009-03-12 08:42:43.584 'SecondarySanProvider' 2808 trivia] Environment TMP=C:\WINDOWS\TEMP will be set for the script
[2009-03-12 08:42:43.584 'SecondarySanProvider' 2808 trivia] Environment USERPROFILE=C:\Documents and Settings\Default User will be set for the script
[2009-03-12 08:42:43.584 'SecondarySanProvider' 2808 trivia] Environment VSEDEFLOGDIR=C:\Documents and Settings\All Users\Application Data\McAfee\DesktopProtection will be set for the script
[2009-03-12 08:42:43.584 'SecondarySanProvider' 2808 trivia] Environment windir=C:\WINDOWS will be set for the script
[2009-03-12 08:42:43.584 'SysCommandLineWin32' 2808 verbose] Starting process: "E:\\Program Files\\VMware\\VMware Site Recovery Manager\\external\\perl-5.8.8\\bin\\perl.exe" "E:/Program Files/VMware/VMware Site Recovery Manager/scripts/SAN/LeftHand Networks/command.pl"
[2009-03-12 08:42:43.599 'RSStorageOperation-10555-Task' 2796 verbose] YieldableRecoveryTask::CreateMultiLocalTaskWrapper
[2009-03-12 08:42:43.599 'RSStorageOperation-10555-Task' 2796 verbose] YieldableRecoveryTask::AddTaskToMultiTaskWrapper
[2009-03-12 08:42:43.599 'RSStorageOperation-10555-Task' 2796 info] Work function yielded
[2009-03-12 08:42:43.599 'RSStorageOperation-10555-Task' 2796 verbose] Progress is unchanged
[2009-03-12 08:42:47.978 'LicenseManager' 2840 verbose] FlexLM: Server Available.
[2009-03-12 08:42:47.978 'LicenseManager' 2840 info] FlexLM: The feature 'PROD_SRM' is not present on the license server or has expired.
[2009-03-12 08:42:47.978 'LicenseManager' 2840 info] FlexLM: The feature 'SRM_PROTECTED_HOST' is not present on the license server or has expired.
[2009-03-12 08:42:58.026 'LocalSiteStatus' 2840 verbose] Free disk space: 14727 Mb
[2009-03-12 08:42:58.026 'LocalSiteStatus' 2840 verbose] CPU usage: 3 %
[2009-03-12 08:42:58.026 'LocalSiteStatus' 2840 verbose] Available memory: 307 Mb
[2009-03-12 08:43:03.050 'BeginImageTest-Task' 2820 verbose] Progress advanced to 1
[2009-03-12 08:43:03.050 'RSStorageOperation-10555-Task' 2820 verbose] Progress advanced to 1
[2009-03-12 08:43:03.050 'RSStorageOperationList-10554-Task' 2820 info] MRT-Progress Task RSStorageOperation-10555-75 for dr.secondary.RecoveryStep:RSStorageOperation-10555 1
[2009-03-12 08:43:03.050 'RSStorageOperationList-10554-Task' 2820 verbose] Progress advanced to 1
[2009-03-12 08:43:03.050 'RootStepList-10541-Task' 2792 info] MRT-Progress Task RSStorageOperationList-10554-73 for dr.secondary.RecoveryStep:RSStorageOperationList-10554 1
[2009-03-12 08:43:03.050 'RootStepList-10541-Task' 2792 verbose] Progress is unchanged
[2009-03-12 08:43:15.678 'SecondarySanProvider' 2808 info] testFailover exited with exit code 0
[2009-03-12 08:43:15.678 'SecondarySanProvider' 2808 trivia] testFailover's output:
"E:\Program Files\VMware\VMware Site Recovery Manager\/scripts/SAN/LeftHand Networks/jre/bin/java" -cp "E:\Program Files\VMware\VMware Site Recovery Manager\/scripts/SAN/LeftHand Networks/UI.jar" com.lefthandnetworks.commandline.Srm.Srm < "E:\Program Files\VMware\VMware Site Recovery Manager\/scripts/SAN/LeftHand Networks/XMLinput.xml""
[#2] UNEXPECTED: There was no writable space on snapshot named "SRM_LV_Sch_RS_1_Rmt.398" to delete, continuing...
[#2] NOTE: Had this been a real failover the remote parent volume named "SRM_LV_Replica" would have be changed to a primary volume, continuing...
[#2] ADDED: Added volume or snpashot "SRM_LV_Sch_RS_1_Rmt.398" to the volume list named "1", continuing...
[#2] ADDED: Added volume or snpashot "SRM_LV_Sch_RS_1_Rmt.398" to the volume list named "2", continuing...
[#2] ERROR: command to address 10.19.49.64 failed because Connection reset
[#2] UNEXPECTED: There was no writable space on snapshot named "SRM_LV_Sch_RS_1_Rmt.398" to delete, continuing...
[#2] NOTE: Had this been a real failover the remote parent volume named "SRM_LV_Replica" would have be changed to a primary volume, continuing...
[2009-03-12 08:43:15.694 'SecondarySanProvider' 2808 trivia] 'testFailover' returned <?xml version="1.0" encoding="ISO-8859-1"?>
[#2] <Response>
[#2]     <ReturnCode>0</ReturnCode>
[#2]     <InitiatorGroupList>
[#2]         <InitiatorGroup id="23;rsfpcitrixesx1">
[#2]             <Initiator
[#2]                 id="iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07" type="ISCSI"/>
[#2]         </InitiatorGroup>
[#2]         <InitiatorGroup id="21;rsfpcitrixesx2">
[#2]             <Initiator
[#2]                 id="iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d" type="ISCSI"/>
[#2]         </InitiatorGroup>
[#2]     </InitiatorGroupList>
[#2]     <ReplicaLunList>
[#2]         <ReplicaLun key="007C420D5785E225AE6F82584BC73585;SRM_LV;30;SRM_LV_Sch_RS_1_Pri">
[#2]             <Number
[#2]                 targetId="iqn.2003-10.com.lefthandnetworks:srm-fp:3209:srm-lv-sch-rs-1-rmt-398" initiatorGroupId="21;rsfpcitrixesx2">0</Number>
[#2]             <Number
[#2]                 targetId="iqn.2003-10.com.lefthandnetworks:srm-fp:3209:srm-lv-sch-rs-1-rmt-398" initiatorGroupId="23;rsfpcitrixesx1">0</Number>
[#2]         </ReplicaLun>
[#2]     </ReplicaLunList>
[#2] </Response>
[2009-03-12 08:43:15.694 'SecondarySanProvider' 2808 info] Return code for testFailover: 0
[2009-03-12 08:43:15.694 'SecondarySanProvider' 2808 trivia] 'Prepare storage for group 'shadow-group-4245' for recovery' took 32.647 seconds
[2009-03-12 08:43:15.694 'BeginImageTest-Task' 2808 verbose] Progress advanced to 15
[2009-03-12 08:43:15.694 'SecondarySanProvider' 2808 trivia] Persisting SecondarySanProvider to database
[2009-03-12 08:43:15.694 'SecondarySanProvider' 2808 verbose] Saving Secondary::SanProvider to DB object
[2009-03-12 08:43:15.694 'SecondarySanProvider' 2808 verbose] Saved Secondary::SanProvider to DB object
[2009-03-12 08:43:15.694 'SecondarySanProvider' 2808 trivia] 'Save Secondary::SanProvider to DB object' took 0 seconds
[2009-03-12 08:43:15.694 'RSStorageOperation-10555-Task' 2796 verbose] Progress advanced to 15
[2009-03-12 08:43:15.694 'RSStorageOperationList-10554-Task' 2636 info] MRT-Progress Task RSStorageOperation-10555-75 for dr.secondary.RecoveryStep:RSStorageOperation-10555 15
[2009-03-12 08:43:15.694 'RSStorageOperationList-10554-Task' 2636 verbose] Progress advanced to 15
[2009-03-12 08:43:15.694 'RootStepList-10541-Task' 2796 info] MRT-Progress Task RSStorageOperationList-10554-73 for dr.secondary.RecoveryStep:RSStorageOperationList-10554 15
[2009-03-12 08:43:15.694 'RootStepList-10541-Task' 2796 verbose] Progress advanced to 1
[2009-03-12 08:43:15.694 'RecoveryContext-70-Task' 2636 verbose] Progress advanced to 1
[2009-03-12 08:43:15.740 'SecondarySanProvider' 2808 trivia] Status of array 'array-6707' is set to 'syncing'
[2009-03-12 08:43:15.740 'SecondarySanProvider' 2808 info] Command Line for discoverArrays: "E:\Program Files\VMware\VMware Site Recovery Manager\external\perl-5.8.8\bin\perl.exe" "E:/Program Files/VMware/VMware Site Recovery Manager/scripts/SAN/LeftHand Networks/command.pl"
[2009-03-12 08:43:15.740 'SecondarySanProvider' 2808 verbose] Input for discoverArrays: <?xml version="1.0" encoding="UTF-8"?>
[#2] <Command>
[#2]   <Name>discoverArrays</Name>
[#2]   <ConnectSpec>
[#2]     <Name>SAN/iQ</Name>
[#2]     <Address>10.19.49.64</Address>
[#2]     <Address>10.19.49.62</Address>
[#2]     <Username>gotts</Username>
[#2]     <Password>********</Password>
[#2]   </ConnectSpec>
[#2]   <OutputFile>C:\WINDOWS\TEMP\vmware-SYSTEM\dr-sanprovider0</OutputFile>
[#2]   <LogLevel>trivia</LogLevel>
[#2] </Command>
[2009-03-12 08:43:15.740 'SecondarySanProvider' 2808 trivia] Environment ALLUSERSPROFILE=C:\Documents and Settings\All Users will be set for the script
[2009-03-12 08:43:15.740 'SecondarySanProvider' 2808 trivia] Environment ClusterLog=C:\WINDOWS\Cluster\cluster.log will be set for the script
[2009-03-12 08:43:15.740 'SecondarySanProvider' 2808 trivia] Environment CommonProgramFiles=C:\Program Files\Common Files will be set for the script
[2009-03-12 08:43:15.740 'SecondarySanProvider' 2808 trivia] Environment COMPUTERNAME=RSFP2K3VC25 will be set for the script
[2009-03-12 08:43:15.740 'SecondarySanProvider' 2808 trivia] Environment ComSpec=C:\WINDOWS\system32\cmd.exe will be set for the script
[2009-03-12 08:43:15.740 'SecondarySanProvider' 2808 trivia] Environment DEFLOGDIR=C:\Documents and Settings\All Users\Application Data\McAfee\DesktopProtection will be set for the script
[2009-03-12 08:43:15.740 'SecondarySanProvider' 2808 trivia] Environment FP_NO_HOST_CHECK=NO will be set for the script
[2009-03-12 08:43:15.740 'SecondarySanProvider' 2808 trivia] Environment NUMBER_OF_PROCESSORS=1 will be set for the script
[2009-03-12 08:43:15.740 'SecondarySanProvider' 2808 trivia] Environment OS=Windows_NT will be set for the script
[2009-03-12 08:43:15.740 'SecondarySanProvider' 2808 trivia] Environment Path=C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\Program Files\Microsoft SQL Server\90\Tools\binn\ will be set for the script
[2009-03-12 08:43:15.740 'SecondarySanProvider' 2808 trivia] Environment PATHEXT=.COM;.EXE;.BAT;.CMD;.VBS;.VBE;.JS;.JSE;.WSF;.WSH will be set for the script
[2009-03-12 08:43:15.740 'SecondarySanProvider' 2808 trivia] Environment PROCESSOR_ARCHITECTURE=x86 will be set for the script
[2009-03-12 08:43:15.740 'SecondarySanProvider' 2808 trivia] Environment PROCESSOR_IDENTIFIER=x86 Family 16 Model 2 Stepping 3, AuthenticAMD will be set for the script
[2009-03-12 08:43:15.740 'SecondarySanProvider' 2808 trivia] Environment PROCESSOR_LEVEL=16 will be set for the script
[2009-03-12 08:43:15.740 'SecondarySanProvider' 2808 trivia] Environment PROCESSOR_REVISION=0203 will be set for the script
[2009-03-12 08:43:15.740 'SecondarySanProvider' 2808 trivia] Environment ProgramFiles=C:\Program Files will be set for the script
[2009-03-12 08:43:15.740 'SecondarySanProvider' 2808 trivia] Environment SystemDrive=C: will be set for the script
[2009-03-12 08:43:15.740 'SecondarySanProvider' 2808 trivia] Environment SystemRoot=C:\WINDOWS will be set for the script
[2009-03-12 08:43:15.740 'SecondarySanProvider' 2808 trivia] Environment TEMP=C:\WINDOWS\TEMP will be set for the script
[2009-03-12 08:43:15.740 'SecondarySanProvider' 2808 trivia] Environment TMP=C:\WINDOWS\TEMP will be set for the script
[2009-03-12 08:43:15.740 'SecondarySanProvider' 2808 trivia] Environment USERPROFILE=C:\Documents and Settings\Default User will be set for the script
[2009-03-12 08:43:15.740 'SecondarySanProvider' 2808 trivia] Environment VSEDEFLOGDIR=C:\Documents and Settings\All Users\Application Data\McAfee\DesktopProtection will be set for the script
[2009-03-12 08:43:15.740 'SecondarySanProvider' 2808 trivia] Environment windir=C:\WINDOWS will be set for the script
[2009-03-12 08:43:15.740 'SysCommandLineWin32' 2808 verbose] Starting process: "E:\\Program Files\\VMware\\VMware Site Recovery Manager\\external\\perl-5.8.8\\bin\\perl.exe" "E:/Program Files/VMware/VMware Site Recovery Manager/scripts/SAN/LeftHand Networks/command.pl"
[2009-03-12 08:43:19.311 'SecondarySanProvider' 2808 info] discoverArrays exited with exit code 0
[2009-03-12 08:43:19.311 'SecondarySanProvider' 2808 trivia] discoverArrays's output:
"E:\Program Files\VMware\VMware Site Recovery Manager\/scripts/SAN/LeftHand Networks/jre/bin/java" -cp "E:\Program Files\VMware\VMware Site Recovery Manager\/scripts/SAN/LeftHand Networks/UI.jar" com.lefthandnetworks.commandline.Srm.Srm < "E:\Program Files\VMware\VMware Site Recovery Manager\/scripts/SAN/LeftHand Networks/XMLinput.xml""
[#2] #
[#2] # An unexpected error has been detected by Java Runtime Environment:
[#2] #
[#2] #  EXCEPTION_ACCESS_VIOLATION (0xc0000005) at pc=0x6d894136, pid=132, tid=2716
[#2] #
[#2] # Java VM: Java HotSpot(TM) Client VM (1.6.0_01-b06 mixed mode)
[#2] # Problematic frame:
[#2] #
[#2] # An error report file with more information is saved as hs_err_pid132.log
[#2] #
[#2] # If you would like to submit a bug report, please visit:
[#2] #
[2009-03-12 08:43:19.311 'SecondarySanProvider' 2808 trivia] 'discoverArrays' returned
[2009-03-12 08:43:19.311 'SecondarySanProvider' 2808 error] Failed to retrieve script results
[2009-03-12 08:43:19.311 'SecondarySanProvider' 2808 trivia] Status of array 'array-6707' is set to 'syncFailed'
[2009-03-12 08:43:19.311 'SecondarySanProvider' 2808 warning] Failed to re-sync with storage array: Unexpected exception 'class Vmacore::Xml::XMLParseException' XML document is empty
[2009-03-12 08:43:19.311 'SecondarySanProvider' 2808 warning] Failed to refresh array information during recovery: Unexpected exception 'class Vmacore::Xml::XMLParseException' XML document is empty
[2009-03-12 08:43:19.311 'SecondarySanProvider' 2808 verbose] Rescanning 2 host(s) 1 time(s)
[2009-03-12 08:43:19.311 'SecondarySanProvider' 2808 verbose] Rescanning host 'host-559'
[2009-03-12 08:43:19.311 'DatastoreLocator.RescanHost-Task' 2808 verbose] Task created
[2009-03-12 08:43:19.311 'SimpleTaskManager' 2808 verbose] Adding task DatastoreLocator.RescanHost-76
[2009-03-12 08:43:19.311 'DatastoreLocator.RescanHost-Task' 2808 info] State set to running
[2009-03-12 08:43:19.311 'DatastoreLocator.RescanHost-Task' 2808 verbose] Scheduling work item
[2009-03-12 08:43:19.311 'SecondarySanProvider' 2808 verbose] Rescanning host 'host-594'
[2009-03-12 08:43:19.311 'DatastoreLocator.RescanHost-Task' 2808 verbose] Task created
[2009-03-12 08:43:19.311 'SimpleTaskManager' 2808 verbose] Adding task DatastoreLocator.RescanHost-77
[2009-03-12 08:43:19.311 'DatastoreLocator.RescanHost-Task' 2808 info] State set to running
[2009-03-12 08:43:19.311 'DatastoreLocator.RescanHost-Task' 2808 verbose] Scheduling work item
[2009-03-12 08:43:19.311 'SecondarySanProvider' 2808 trivia] MLTW, handling task progress
[2009-03-12 08:43:19.311 'SecondarySanProvider' 2808 trivia] MLTW, handling task state
[2009-03-12 08:43:19.311 'SecondarySanProvider' 2808 trivia] MLTW, handling task progress
[2009-03-12 08:43:19.311 'SecondarySanProvider' 2808 trivia] MLTW, handling task state
[2009-03-12 08:43:19.311 'DatastoreLocator.RescanHost-Task' 2796 info] Running work method
[2009-03-12 08:43:19.311 'DatastoreLocator.RescanHost-Task' 2820 info] Running work method
[2009-03-12 08:43:42.925 'SimpleTaskManager' 2780 verbose] Scanning for tasks to reap
[2009-03-12 08:43:58.027 'LocalSiteStatus' 2836 verbose] Free disk space: 14727 Mb
[2009-03-12 08:43:58.027 'LocalSiteStatus' 2836 verbose] CPU usage: 1 %
[2009-03-12 08:43:58.027 'LocalSiteStatus' 2836 verbose] Available memory: 339 Mb
[2009-03-12 08:43:59.778 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-562:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 13782482944,
}
[2009-03-12 08:43:59.901 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-580:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 572228894720,
}
[2009-03-12 08:43:59.901 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-994:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info",
   op = "assign",
   val = (vim.host.VmfsDatastoreInfo) {
      dynamicType = <unset>,
      name = "snap-00000002-RSLVVSAN_OS",
      url = "sanfs://vmfs_uuid:49b90387-2d0f8e66-4a89-0015179395a3/",
      freeSpace = 84157661184,
      maxFileSize = 274877906944,
      vmfs = (vim.host.VmfsVolume) {
         dynamicType = <unset>,
         type = "VMFS",
         name = "snap-00000002-RSLVVSAN_OS",
         capacity = 107105746944,
         blockSizeMb = 1,
         maxBlocks = 262144,
         majorVersion = 3,
         version = "3.21",
         uuid = "49b90387-2d0f8e66-4a89-0015179395a3",
         extent = (vim.host.ScsiDisk.Partition) [
            (vim.host.ScsiDisk.Partition) {
               dynamicType = <unset>,
               diskName = "vmhba40:24:0",
               partition = 1,
            }
         ],
         vmfsUpgradable = false,
      },
   },
}
[2009-03-12 08:43:59.901 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-994:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "vm",
   op = "assign",
   val = (ManagedObjectReference) [],
}
[2009-03-12 08:43:59.901 'SanConfigManager' 2812 trivia] Lun group computation is disabled
[2009-03-12 08:43:59.901 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-582:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 643100049408,
}
[2009-03-12 08:43:59.901 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-574:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 6325010432,
}
[2009-03-12 08:43:59.901 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-584:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 597688320,
}
[2009-03-12 08:43:59.901 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-576:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 977272832,
}
[2009-03-12 08:43:59.901 'SanConfigManager' 2812 trivia] Received update for vim.Datacenter:datacenter-553:
(vmodl.query.PropertyCollector.Change) [
   (vmodl.query.PropertyCollector.Change) {
      dynamicType = <unset>,
      name = "datastore",
      op = "add",
      val = 'vim.Datastore:datastore-994',
   }
]
[2009-03-12 08:43:59.901 'SanConfigManager' 2812 verbose] Noticed new datastore 'datastore-994' in datacenter 'datacenter-553'
[2009-03-12 08:44:00.992 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-568:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 15395192832,
}
[2009-03-12 08:44:00.992 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-580:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 572233089024,
}
[2009-03-12 08:44:00.992 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-584:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 599785472,
}
[2009-03-12 08:44:00.992 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-576:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 981467136,
}
[2009-03-12 08:44:00.992 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-582:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 643104243712,
}
[2009-03-12 08:44:00.992 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-574:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 6329204736,
}
[2009-03-12 08:44:01.007 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-619:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 84699774976,
}
[2009-03-12 08:44:05.371 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-568:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 3580887040,
}
[2009-03-12 08:44:05.386 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-580:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 572228894720,
}
[2009-03-12 08:44:05.386 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-584:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 597688320,
}
[2009-03-12 08:44:05.386 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-576:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 977272832,
}
[2009-03-12 08:44:05.386 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-582:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 643100049408,
}
[2009-03-12 08:44:05.386 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-574:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 6325010432,
}
[2009-03-12 08:44:05.386 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-619:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 84431339520,
}
[2009-03-12 08:44:06.216 'DatastoreLocator.RescanHost-Task' 2796 info] Work function completed successfully
[2009-03-12 08:44:06.216 'DatastoreLocator.RescanHost-Task' 2796 info] State set to success
[2009-03-12 08:44:06.216 'SecondarySanProvider' 2796 trivia] MLTW, handling task state
[2009-03-12 08:44:06.216 'SecondarySanProvider' 2796 trivia] MLTW, number of active tasks set to 1
[2009-03-12 08:44:07.322 'BeginImageTest-Task' 2796 verbose] Progress advanced to 16
[2009-03-12 08:44:07.322 'RSStorageOperation-10555-Task' 2796 verbose] Progress advanced to 16
[2009-03-12 08:44:07.322 'RSStorageOperationList-10554-Task' 2796 info] MRT-Progress Task RSStorageOperation-10555-75 for dr.secondary.RecoveryStep:RSStorageOperation-10555 16
[2009-03-12 08:44:07.322 'RSStorageOperationList-10554-Task' 2796 verbose] Progress advanced to 16
[2009-03-12 08:44:07.322 'RootStepList-10541-Task' 2828 info] MRT-Progress Task RSStorageOperationList-10554-73 for dr.secondary.RecoveryStep:RSStorageOperationList-10554 16
[2009-03-12 08:44:07.322 'RootStepList-10541-Task' 2828 verbose] Progress is unchanged
[2009-03-12 08:44:09.980 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-580:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 572233089024,
}
[2009-03-12 08:44:09.980 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-576:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 981467136,
}
[2009-03-12 08:44:09.980 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-994:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.vmfs.extent",
   op = "assign",
   val = (vim.host.ScsiDisk.Partition) [
      (vim.host.ScsiDisk.Partition) {
         dynamicType = <unset>,
         diskName = "vmhba40:25:0",
         partition = 1,
      }
   ],
}
[2009-03-12 08:44:09.980 'SanConfigManager' 2812 verbose] Added datastore 'datastore-994' with 1 extents to the cache
[2009-03-12 08:44:09.980 'SanConfigManager' 2812 verbose] Noticed new extent of datastore 'datastore-994'
[2009-03-12 08:44:09.980 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-568:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 15395192832,
}
[2009-03-12 08:44:09.980 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-582:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 643104243712,
}
[2009-03-12 08:44:09.980 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-574:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 6329204736,
}
[2009-03-12 08:44:09.980 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-619:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 84699774976,
}
[2009-03-12 08:44:09.980 'SanConfigManager' 2812 trivia] Received update for vim.Datastore:datastore-584:
(vmodl.query.PropertyCollector.Change) {
   dynamicType = <unset>,
   name = "info.freeSpace",
   op = "assign",
   val = 599785472,
}
[2009-03-12 08:44:10.010 'DatastoreLocator.RescanHost-Task' 2820 info] Work function completed successfully
[2009-03-12 08:44:10.010 'DatastoreLocator.RescanHost-Task' 2820 info] State set to success
[2009-03-12 08:44:10.010 'SecondarySanProvider' 2820 trivia] MLTW, handling task state
[2009-03-12 08:44:10.010 'SecondarySanProvider' 2820 trivia] MLTW, number of active tasks set to 0
[2009-03-12 08:44:10.010 'SecondarySanProvider' 2808 trivia] MLTW completed, woken up
[2009-03-12 08:44:10.010 'SecondarySanProvider' 2808 trivia] 'Rescan 2 hosts' took 50.699 seconds
[2009-03-12 08:44:10.010 'BeginImageTest-Task' 2808 verbose] Progress advanced to 40
[2009-03-12 08:44:10.010 'RSStorageOperation-10555-Task' 2820 verbose] Progress advanced to 40
[2009-03-12 08:44:10.010 'RSStorageOperationList-10554-Task' 2820 info] MRT-Progress Task RSStorageOperation-10555-75 for dr.secondary.RecoveryStep:RSStorageOperation-10555 40
[2009-03-12 08:44:10.010 'RSStorageOperationList-10554-Task' 2820 verbose] Progress advanced to 40
[2009-03-12 08:44:10.010 'RootStepList-10541-Task' 2840 info] MRT-Progress Task RSStorageOperationList-10554-73 for dr.secondary.RecoveryStep:RSStorageOperationList-10554 40
[2009-03-12 08:44:10.010 'RootStepList-10541-Task' 2840 verbose] Progress advanced to 3
[2009-03-12 08:44:10.010 'RecoveryContext-70-Task' 2636 verbose] Progress advanced to 3
[2009-03-12 08:44:10.057 'SecondarySanProvider' 2808 trivia] Found 1 properties for object 'vim.Network:network-956'
[2009-03-12 08:44:10.057 'SecondarySanProvider' 2808 verbose] Found network 'testBubble-1 group' with MoId 'network-956'
[2009-03-12 08:44:10.057 'SecondarySanProvider' 2808 trivia] Found 1 properties for object 'vim.Network:network-588'
[2009-03-12 08:44:10.057 'SecondarySanProvider' 2808 verbose] Found network 'VM Network' with MoId 'network-588'
[2009-03-12 08:44:10.057 'SecondarySanProvider' 2808 trivia] Found 1 properties for object 'vim.Network:network-616'
[2009-03-12 08:44:10.057 'SecondarySanProvider' 2808 verbose] Found network 'VMNetwork' with MoId 'network-616'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Skipping HBA which is neither FC nor iSCSI:
(vim.host.ParallelScsiHba) {
[#2]    dynamicType = <unset>,
[#2]    key = "key-vim.host.ParallelScsiHba-vmhba0",
[#2]    device = "vmhba0",
[#2]    bus = 12,
[#2]    status = "unknown",
[#2]    model = "ServeRAID 8k/8k-l8 (Aurora)",
[#2]    driver = "aacraid_esx30",
[#2]    pci = "0c:00.0",
[#2] }
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;0;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:0' and 'host-559;020000000060060160d9001d0006dac2bb3731dc11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;1;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:1' and 'host-559;020001000060060160d9001d0030b4a5d93731dc11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;2;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:2' and 'host-559;020002000060060160d9001d00588d1c4f3b31dc11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;3;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:3' and 'host-559;020003000060060160d9001d005a8d1c4f3b31dc11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;4;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:4' and 'host-559;020004000060060160d9001d00c4a5900e3831dc11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;5;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:5' and 'host-559;020005000060060160d9001d0007dac2bb3731dc11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;6;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:6' and 'host-559;020006000060060160d9001d0031b4a5d93731dc11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;7;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:7' and 'host-559;020007000060060160d9001d00598d1c4f3b31dc11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;8;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:8' and 'host-559;020008000060060160d9001d005b8d1c4f3b31dc11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;9;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:9' and 'host-559;020009000060060160d9001d00c5a5900e3831dc11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;10;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:10' and 'host-559;02000a000060060160d9001d00c6a5900e3831dc11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;11;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:11' and 'host-559;02000b000060060160d9001d00c7a5900e3831dc11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;12;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:12' and 'host-559;02000c000060060160d9001d00a4641e2b0208de11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;13;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:13' and 'host-559;02000d000060060160d9001d00a6641e2b0208de11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;14;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:14' and 'host-559;02000e000060060160d9001d00539241310208de11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;15;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:15' and 'host-559;02000f000060060160d9001d00a5641e2b0208de11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;16;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:16' and 'host-559;020010000060060160d9001d00529241310208de11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;17;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:17' and 'host-559;020011000060060160d9001d00c59b80800208de11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;18;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:18' and 'host-559;020012000060060160d9001d00c79b80800208de11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;19;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:19' and 'host-559;020013000060060160d9001d002c0680860208de11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;20;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:20' and 'host-559;020014000060060160d9001d002e0680860208de11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;21;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:21' and 'host-559;020015000060060160d9001d00300680860208de11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;22;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:22' and 'host-559;020016000060060160d9001d00c49b80800208de11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;23;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:23' and 'host-559;020017000060060160d9001d00c69b80800208de11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;24;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:24' and 'host-559;020018000060060160d9001d00c89b80800208de11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;25;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:25' and 'host-559;020019000060060160d9001d002d0680860208de11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;26;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-559;vmhba40:0:26' and 'host-559;02001a000060060160d9001d002f0680860208de11524149442035'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;0;iqn.2003-10.com.lefthandnetworks:srm-fp:31:srm-fp-data' with keys 'host-559;vmhba40:4:0' and 'host-559;02000000006000eb32866f8d05000000000000001f695343534944'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;0;iqn.2003-10.com.lefthandnetworks:srm-fp:19:srm-fp' with keys 'host-559;vmhba40:5:0' and 'host-559;02000000006000eb32866f8d050000000000000013695343534944'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx1-78b77d07;0;iqn.2003-10.com.lefthandnetworks:srm-fp:3209:srm-lv-sch-rs-1-rmt-398' with keys 'host-559;vmhba40:24:0' and 'host-559;02000000006000eb32866f8d050000000000000c89695343534944'
[2009-03-12 08:44:10.241 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-559;vmhba40:5:0' with key 'host-559;49ae0015-aa1568ea-2a95-0015179395a3;0'
[2009-03-12 08:44:10.256 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-559;vmhba40:0:0' with key 'host-559;46c32b3c-bff1c5fd-bb9e-00145e7a0a84;0'
[2009-03-12 08:44:10.256 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-559;vmhba40:0:1' with key 'host-559;46caf265-8f3a75d0-4423-001a6406534d;0'
[2009-03-12 08:44:10.256 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-559;vmhba40:0:2' with key 'host-559;46b883ce-afcc3640-7e72-001a6406534d;0'
[2009-03-12 08:44:10.256 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-559;vmhba40:0:3' with key 'host-559;46b88414-066b85a8-d759-001a6406534d;0'
[2009-03-12 08:44:10.256 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-559;vmhba40:0:4' with key 'host-559;46cb60d5-761417f8-f9c2-00145edccd5f;0'
[2009-03-12 08:44:10.256 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-559;vmhba40:0:5' with key 'host-559;46b848f8-b54b0b38-c693-00145edccd5f;0'
[2009-03-12 08:44:10.256 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-559;vmhba40:0:6' with key 'host-559;48f4bf69-8dee7db8-140f-00145edccd5f;0'
[2009-03-12 08:44:10.256 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-559;vmhba40:0:7' with key 'host-559;48e0dd30-85c18ad0-81cd-00145edccd5f;0'
[2009-03-12 08:44:10.256 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-559;vmhba40:0:8' with key 'host-559;48e0dd7d-e460f5d0-aff7-00145edccd5f;0'
[2009-03-12 08:44:10.256 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-559;vmhba40:0:9' with key 'host-559;46cd8d81-2a90a218-3f5a-001a6406534d;0'
[2009-03-12 08:44:10.256 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-559;vmhba40:0:10' with key 'host-559;46cd8ca4-4f6e0670-9f82-001a6406534d;0'
[2009-03-12 08:44:10.256 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-559;vmhba40:0:11' with key 'host-559;46c337be-0884b1e0-2c73-00145e686fde;0'
[2009-03-12 08:44:10.256 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-559;vmhba40:4:0' with key 'host-559;49adfff1-dfdb8cf8-b415-0015179395a3;0'
[2009-03-12 08:44:10.256 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-559;vmhba40:24:0' with key 'host-559;49b90387-2d0f8e66-4a89-0015179395a3;0'
[2009-03-12 08:44:10.517 'SecondarySanProvider' 2808 trivia] Skipping HBA which is neither FC nor iSCSI:
(vim.host.ParallelScsiHba) {
[#2]    dynamicType = <unset>,
[#2]    key = "key-vim.host.ParallelScsiHba-vmhba0",
[#2]    device = "vmhba0",
[#2]    bus = 12,
[#2]    status = "unknown",
[#2]    model = "ServeRAID 8k/8k-l8 (Aurora)",
[#2]    driver = "aacraid_esx30",
[#2]    pci = "0c:00.0",
[#2] }
[2009-03-12 08:44:10.517 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;0;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:0' and 'host-594;020000000060060160d9001d0006dac2bb3731dc11524149442035'
[2009-03-12 08:44:10.517 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;1;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:1' and 'host-594;020001000060060160d9001d0030b4a5d93731dc11524149442035'
[2009-03-12 08:44:10.517 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;2;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:2' and 'host-594;020002000060060160d9001d00588d1c4f3b31dc11524149442035'
[2009-03-12 08:44:10.517 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;3;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:3' and 'host-594;020003000060060160d9001d005a8d1c4f3b31dc11524149442035'
[2009-03-12 08:44:10.517 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;4;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:4' and 'host-594;020004000060060160d9001d00c4a5900e3831dc11524149442035'
[2009-03-12 08:44:10.517 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;5;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:5' and 'host-594;020005000060060160d9001d0007dac2bb3731dc11524149442035'
[2009-03-12 08:44:10.517 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;6;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:6' and 'host-594;020006000060060160d9001d0031b4a5d93731dc11524149442035'
[2009-03-12 08:44:10.517 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;7;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:7' and 'host-594;020007000060060160d9001d00598d1c4f3b31dc11524149442035'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;8;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:8' and 'host-594;020008000060060160d9001d005b8d1c4f3b31dc11524149442035'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;9;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:9' and 'host-594;020009000060060160d9001d00c5a5900e3831dc11524149442035'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;10;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:10' and 'host-594;02000a000060060160d9001d00c6a5900e3831dc11524149442035'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;11;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:11' and 'host-594;02000b000060060160d9001d00c7a5900e3831dc11524149442035'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;12;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:12' and 'host-594;02000c000060060160d9001d00a4641e2b0208de11524149442035'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;13;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:13' and 'host-594;02000d000060060160d9001d00a6641e2b0208de11524149442035'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;14;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:14' and 'host-594;02000e000060060160d9001d00539241310208de11524149442035'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;15;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:15' and 'host-594;02000f000060060160d9001d00a5641e2b0208de11524149442035'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;16;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:16' and 'host-594;020010000060060160d9001d00529241310208de11524149442035'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;17;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:17' and 'host-594;020011000060060160d9001d00c59b80800208de11524149442035'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;18;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:18' and 'host-594;020012000060060160d9001d00c79b80800208de11524149442035'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;19;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:19' and 'host-594;020013000060060160d9001d002c0680860208de11524149442035'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;20;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:20' and 'host-594;020014000060060160d9001d002e0680860208de11524149442035'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;21;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:21' and 'host-594;020015000060060160d9001d00300680860208de11524149442035'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;22;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:22' and 'host-594;020016000060060160d9001d00c49b80800208de11524149442035'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;23;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:23' and 'host-594;020017000060060160d9001d00c69b80800208de11524149442035'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;24;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:24' and 'host-594;020018000060060160d9001d00c89b80800208de11524149442035'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;25;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:25' and 'host-594;020019000060060160d9001d002d0680860208de11524149442035'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;26;iqn.1992-04.com.emc:cx.apm00072103469.b0' with keys 'host-594;vmhba40:0:26' and 'host-594;02001a000060060160d9001d002f0680860208de11524149442035'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;0;iqn.2003-10.com.lefthandnetworks:srm-fp:31:srm-fp-data' with keys 'host-594;vmhba40:4:0' and 'host-594;02000000006000eb32866f8d05000000000000001f695343534944'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;0;iqn.2003-10.com.lefthandnetworks:srm-fp:19:srm-fp' with keys 'host-594;vmhba40:5:0' and 'host-594;02000000006000eb32866f8d050000000000000013695343534944'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added LUN 'iqn.1998-01.com.vmware:rsfpcitrixesx2-06683a9d;0;iqn.2003-10.com.lefthandnetworks:srm-fp:3209:srm-lv-sch-rs-1-rmt-398' with keys 'host-594;vmhba40:25:0' and 'host-594;02000000006000eb32866f8d050000000000000c89695343534944'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-594;vmhba40:0:0' with key 'host-594;46c32b3c-bff1c5fd-bb9e-00145e7a0a84;0'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-594;vmhba40:5:0' with key 'host-594;49ae0015-aa1568ea-2a95-0015179395a3;0'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-594;vmhba40:0:1' with key 'host-594;46caf265-8f3a75d0-4423-001a6406534d;0'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-594;vmhba40:0:2' with key 'host-594;46b883ce-afcc3640-7e72-001a6406534d;0'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-594;vmhba40:0:3' with key 'host-594;46b88414-066b85a8-d759-001a6406534d;0'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-594;vmhba40:0:4' with key 'host-594;46cb60d5-761417f8-f9c2-00145edccd5f;0'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-594;vmhba40:0:5' with key 'host-594;46b848f8-b54b0b38-c693-00145edccd5f;0'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-594;vmhba40:0:6' with key 'host-594;48f4bf69-8dee7db8-140f-00145edccd5f;0'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-594;vmhba40:0:7' with key 'host-594;48e0dd30-85c18ad0-81cd-00145edccd5f;0'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-594;vmhba40:0:8' with key 'host-594;48e0dd7d-e460f5d0-aff7-00145edccd5f;0'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-594;vmhba40:0:9' with key 'host-594;46cd8d81-2a90a218-3f5a-001a6406534d;0'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-594;vmhba40:0:10' with key 'host-594;46cd8ca4-4f6e0670-9f82-001a6406534d;0'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-594;vmhba40:0:11' with key 'host-594;46c337be-0884b1e0-2c73-00145e686fde;0'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-594;vmhba40:4:0' with key 'host-594;49adfff1-dfdb8cf8-b415-0015179395a3;0'
[2009-03-12 08:44:10.533 'SecondarySanProvider' 2808 trivia] Added vmfs extent 'host-594;vmhba40:25:0' with key 'host-594;49b90387-2d0f8e66-4a89-0015179395a3;0'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 3 properties for object 'vim.Datastore:datastore-562'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 3 properties for object 'vim.Datastore:datastore-580'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 3 properties for object 'vim.Datastore:datastore-597'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 4 properties for object 'vim.VirtualMachine:vm-621'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 3 properties for object 'vim.Datastore:datastore-572'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 3 properties for object 'vim.Datastore:datastore-994'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 4 properties for object 'vim.VirtualMachine:vm-613'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 4 properties for object 'vim.VirtualMachine:vm-990'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 3 properties for object 'vim.Datastore:datastore-564'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 3 properties for object 'vim.Datastore:datastore-582'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 3 properties for object 'vim.Datastore:datastore-599'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 3 properties for object 'vim.Datastore:datastore-609'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 4 properties for object 'vim.VirtualMachine:vm-605'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 4 properties for object 'vim.VirtualMachine:vm-623'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 3 properties for object 'vim.Datastore:datastore-574'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 3 properties for object 'vim.Datastore:datastore-619'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 4 properties for object 'vim.VirtualMachine:vm-992'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 1 properties for object 'vim.Datacenter:datacenter-553'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 3 properties for object 'vim.Datastore:datastore-566'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 3 properties for object 'vim.Datastore:datastore-584'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 3 properties for object 'vim.Datastore:datastore-603'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 4 properties for object 'vim.VirtualMachine:vm-607'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 4 properties for object 'vim.VirtualMachine:vm-625'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 3 properties for object 'vim.Datastore:datastore-576'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 4 properties for object 'vim.VirtualMachine:vm-589'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 3 properties for object 'vim.Datastore:datastore-568'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 3 properties for object 'vim.Datastore:datastore-856'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 3 properties for object 'vim.Datastore:datastore-570'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 3 properties for object 'vim.Datastore:datastore-578'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 trivia] Found 4 properties for object 'vim.VirtualMachine:vm-611'
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 verbose] Adding datastore 'EMC_LUN_1_FC_for_OS' with MoId 'datastore-562' and VMFS volume UUID '46b848f8-b54b0b38-c693-00145edccd5f' spanning 1 LUNs
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 verbose] Adding datastore 'EMC_LUN_7' with MoId 'datastore-580' and VMFS volume UUID '48e0dd30-85c18ad0-81cd-00145edccd5f' spanning 1 LUNs
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 verbose] Adding datastore 'EMC_LUN_2_for_SQL_DATA' with MoId 'datastore-572' and VMFS volume UUID '46caf265-8f3a75d0-4423-001a6406534d' spanning 1 LUNs
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 verbose] Adding datastore 'snap-00000002-RSLVVSAN_OS' with MoId 'datastore-994' and VMFS volume UUID '49b90387-2d0f8e66-4a89-0015179395a3' spanning 1 LUNs
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 verbose] Adding datastore 'EMC_Sata1' with MoId 'datastore-564' and VMFS volume UUID '46b883ce-afcc3640-7e72-001a6406534d' spanning 1 LUNs
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 verbose] Adding datastore 'EMC_LUN_82' with MoId 'datastore-582' and VMFS volume UUID '48e0dd7d-e460f5d0-aff7-00145edccd5f' spanning 1 LUNs
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 verbose] Adding datastore 'EMC_LUN_8' with MoId 'datastore-574' and VMFS volume UUID '46cb60d5-761417f8-f9c2-00145edccd5f' spanning 1 LUNs
[2009-03-12 08:44:10.702 'SecondarySanProvider' 2808 verbose] Adding datastore 'RSFPVSAN_OS' with MoId 'datastore-619' and VMFS volume UUID '49ae0015-aa1568ea-2a95-0015179395a3' spanning 1 LUNs
[2009-03-12 08:44:10.717 'SecondarySanProvider' 2808 verbose] Adding datastore 'EMC_Sata2' with MoId 'datastore-566' and VMFS volume UUID '46b88414-066b85a8-d759-001a6406534d' spanning 1 LUNs
[2009-03-12 08:44:10.717 'SecondarySanProvider' 2808 verbose] Adding datastore 'EMC_LUN_3' with MoId 'datastore-584' and VMFS volume UUID '48f4bf69-8dee7db8-140f-00145edccd5f' spanning 1 LUNs
[2009-03-12 08:44:10.717 'SecondarySanProvider' 2808 verbose] Adding datastore 'EMC_LUN_10' with MoId 'datastore-576' and VMFS volume UUID '46cd8ca4-4f6e0670-9f82-001a6406534d' spanning 1 LUNs
[2009-03-12 08:44:10.717 'SecondarySanProvider' 2808 verbose] Adding datastore 'EMC_LUN_0_FC_for_OS' with MoId 'datastore-568' and VMFS volume UUID '46c32b3c-bff1c5fd-bb9e-00145e7a0a84' spanning 1 LUNs
[2009-03-12 08:44:10.717 'SecondarySanProvider' 2808 verbose] Adding datastore 'RSFPVSAN_Data' with MoId 'datastore-856' and VMFS volume UUID '49adfff1-dfdb8cf8-b415-0015179395a3' spanning 1 LUNs
[2009-03-12 08:44:10.717 'SecondarySanProvider' 2808 verbose] Adding datastore 'EMC_Lun_11' with MoId 'datastore-570' and VMFS volume UUID '46c337be-0884b1e0-2c73-00145e686fde' spanning 1 LUNs
[2009-03-12 08:44:10.717 'SecondarySanProvider' 2808 verbose] Adding datastore 'EMC_LUN_9' with MoId 'datastore-578' and VMFS volume UUID '46cd8d81-2a90a218-3f5a-001a6406534d' spanning 1 LUNs
[2009-03-12 08:44:10.717 'SecondarySanProvider' 2808 warning] Unknown LUN target ID 'iqn.2003-10.com.lefthandnetworks:srm-fp:3209:srm-lv-sch-rs-1-rmt-398'
[2009-03-12 08:44:10.717 'SecondarySanProvider' 2808 warning] Unknown LUN target ID 'iqn.2003-10.com.lefthandnetworks:srm-fp:3209:srm-lv-sch-rs-1-rmt-398'
[2009-03-12 08:44:10.717 'SecondarySanProvider' 2808 warning] Shadow datastore for datastore 'sanfs://vmfs_uuid:49adfee5-d396480b-e747-00151793960d/' not found
[2009-03-12 08:44:10.717 'SecondarySanProvider' 2808 verbose] Found 2 VirtualMachines in group 'shadow-group-4245' of 2 ShadowVms
[2009-03-12 08:44:10.748 'SecondarySanProvider' 2808 trivia] Found 5 properties for object 'vim.VirtualMachine:vm-990'
[2009-03-12 08:44:10.748 'SecondarySanProvider' 2808 trivia] Found 5 properties for object 'vim.VirtualMachine:vm-992'
[2009-03-12 08:44:10.748 'SecondarySanProvider' 2808 verbose] Found location properties for 2 out of 2 VMs
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-562'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-580'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-597'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-572'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-576'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-994'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-564'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-568'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-582'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-599'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-856'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-570'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-574'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-619'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-566'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-584'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 verbose] Found 16 datastores mounted on host 'host-594'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/46b848f8-b54b0b38-c693-00145edccd5f/' for datastore 'datastore-562' on host 'host-594'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/46b883ce-afcc3640-7e72-001a6406534d/' for datastore 'datastore-564' on host 'host-594'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/46b88414-066b85a8-d759-001a6406534d/' for datastore 'datastore-566' on host 'host-594'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/46c32b3c-bff1c5fd-bb9e-00145e7a0a84/' for datastore 'datastore-568' on host 'host-594'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/46c337be-0884b1e0-2c73-00145e686fde/' for datastore 'datastore-570' on host 'host-594'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/46caf265-8f3a75d0-4423-001a6406534d/' for datastore 'datastore-572' on host 'host-594'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/46cb60d5-761417f8-f9c2-00145edccd5f/' for datastore 'datastore-574' on host 'host-594'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/46cd8ca4-4f6e0670-9f82-001a6406534d/' for datastore 'datastore-576' on host 'host-594'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/48e0dd30-85c18ad0-81cd-00145edccd5f/' for datastore 'datastore-580' on host 'host-594'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/48e0dd7d-e460f5d0-aff7-00145edccd5f/' for datastore 'datastore-582' on host 'host-594'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/48f4bf69-8dee7db8-140f-00145edccd5f/' for datastore 'datastore-584' on host 'host-594'
[2009-03-12 08:44:10.871 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/497eed20-8fc63190-31eb-0015179395a3/' for datastore 'datastore-597' on host 'host-594'
[2009-03-12 08:44:10.886 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/49a588df-7bff9742-4206-0015179395a3/' for datastore 'datastore-599' on host 'host-594'
[2009-03-12 08:44:10.886 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/49ae0015-aa1568ea-2a95-0015179395a3/' for datastore 'datastore-619' on host 'host-594'
[2009-03-12 08:44:10.886 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/49adfff1-dfdb8cf8-b415-0015179395a3/' for datastore 'datastore-856' on host 'host-594'
[2009-03-12 08:44:10.886 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/49b90387-2d0f8e66-4a89-0015179395a3/' for datastore 'datastore-994' on host 'host-594'
[2009-03-12 08:44:10.886 'SecondarySanProvider' 2808 trivia] 'Prepare VM 'shadow-vm-10300' for test' took 0 seconds
[2009-03-12 08:44:10.886 'SecondarySanProvider' 2808 warning] Failed to prepare shadow vm for recovery: Unexpected MethodFault (dr.san.fault.RecoveredDatastoreNotFound) {
[#2]    dynamicType = <unset>,
[#2]    datastore = (dr.vimext.SanProviderDatastoreLocator) {
[#2]       dynamicType = <unset>,
[#2]       primaryUrl = "sanfs://vmfs_uuid:49adfee5-d396480b-e747-00151793960d/",
[#2]    },
[#2]    reason = (vmodl.MethodFault) null,
[#2]    msg = ""
[#2] }
[2009-03-12 08:44:10.886 'BeginImageTest-Task' 2808 verbose] Progress advanced to 62
[2009-03-12 08:44:10.886 'RSStorageOperation-10555-Task' 2832 verbose] Progress advanced to 62
[2009-03-12 08:44:10.886 'RSStorageOperationList-10554-Task' 2816 info] MRT-Progress Task RSStorageOperation-10555-75 for dr.secondary.RecoveryStep:RSStorageOperation-10555 62
[2009-03-12 08:44:10.886 'RSStorageOperationList-10554-Task' 2816 verbose] Progress advanced to 62
[2009-03-12 08:44:10.886 'RootStepList-10541-Task' 2812 info] MRT-Progress Task RSStorageOperationList-10554-73 for dr.secondary.RecoveryStep:RSStorageOperationList-10554 62
[2009-03-12 08:44:10.902 'RootStepList-10541-Task' 2812 verbose] Progress advanced to 5
[2009-03-12 08:44:10.902 'RecoveryContext-70-Task' 2812 verbose] Progress advanced to 5
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-562'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-580'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-572'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-576'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-994'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-564'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-568'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-582'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-609'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-856'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-570'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-574'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-578'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-619'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-566'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-584'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 trivia] Found 2 properties for object 'vim.Datastore:datastore-603'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 verbose] Found 17 datastores mounted on host 'host-559'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/46b848f8-b54b0b38-c693-00145edccd5f/' for datastore 'datastore-562' on host 'host-559'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/46b883ce-afcc3640-7e72-001a6406534d/' for datastore 'datastore-564' on host 'host-559'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/46b88414-066b85a8-d759-001a6406534d/' for datastore 'datastore-566' on host 'host-559'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/46c32b3c-bff1c5fd-bb9e-00145e7a0a84/' for datastore 'datastore-568' on host 'host-559'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/46c337be-0884b1e0-2c73-00145e686fde/' for datastore 'datastore-570' on host 'host-559'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/46caf265-8f3a75d0-4423-001a6406534d/' for datastore 'datastore-572' on host 'host-559'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/46cb60d5-761417f8-f9c2-00145edccd5f/' for datastore 'datastore-574' on host 'host-559'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/46cd8ca4-4f6e0670-9f82-001a6406534d/' for datastore 'datastore-576' on host 'host-559'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/46cd8d81-2a90a218-3f5a-001a6406534d/' for datastore 'datastore-578' on host 'host-559'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/48e0dd30-85c18ad0-81cd-00145edccd5f/' for datastore 'datastore-580' on host 'host-559'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/48e0dd7d-e460f5d0-aff7-00145edccd5f/' for datastore 'datastore-582' on host 'host-559'
[2009-03-12 08:44:10.917 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/48f4bf69-8dee7db8-140f-00145edccd5f/' for datastore 'datastore-584' on host 'host-559'
[2009-03-12 08:44:10.932 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/49a7e312-8e3be1b2-9bcf-0015179395e8/' for datastore 'datastore-603' on host 'host-559'
[2009-03-12 08:44:10.932 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/49abe999-b16a9f9e-6ac6-0015179395e8/' for datastore 'datastore-609' on host 'host-559'
[2009-03-12 08:44:10.932 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/49ae0015-aa1568ea-2a95-0015179395a3/' for datastore 'datastore-619' on host 'host-559'
[2009-03-12 08:44:10.932 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/49adfff1-dfdb8cf8-b415-0015179395a3/' for datastore 'datastore-856' on host 'host-559'
[2009-03-12 08:44:10.932 'SecondarySanProvider' 2808 verbose] Adding mount path '/vmfs/volumes/49b90387-2d0f8e66-4a89-0015179395a3/' for datastore 'datastore-994' on host 'host-559'
[2009-03-12 08:44:10.932 'SecondarySanProvider' 2808 trivia] 'Prepare VM 'shadow-vm-10379' for test' took 0 seconds
[2009-03-12 08:44:10.932 'SecondarySanProvider' 2808 warning] Failed to prepare shadow vm for recovery: Unexpected MethodFault (dr.san.fault.RecoveredDatastoreNotFound) {
[#2]    dynamicType = <unset>,
[#2]    datastore = (dr.vimext.SanProviderDatastoreLocator) {
[#2]       dynamicType = <unset>,
[#2]       primaryUrl = "sanfs://vmfs_uuid:49adfee5-d396480b-e747-00151793960d/",
[#2]    },
[#2]    reason = (vmodl.MethodFault) null,
[#2]    msg = ""
[#2] }
[2009-03-12 08:44:10.932 'BeginImageTest-Task' 2808 verbose] Progress advanced to 85
[2009-03-12 08:44:10.932 'BeginImageTest-Task' 2808 verbose] Progress advanced to 90
[2009-03-12 08:44:10.932 'SecondarySanProvider' 2808 trivia] 'Prepare 2 VMs in group 'shadow-group-4245' for test' took 0.215 seconds
[2009-03-12 08:44:10.932 'BeginImageTest-Task' 2808 verbose] Result set to (dr.secondary.ReplicationManager.SingleVmFailure) [
[#2]    (dr.secondary.ReplicationManager.SingleVmFailure) {
[#2]       dynamicType = <unset>,
[#2]       vm = 'dr.secondary.ShadowVm:shadow-vm-10300',
[#2]       fault = (dr.san.fault.RecoveredDatastoreNotFound) {
[#2]          dynamicType = <unset>,
[#2]          datastore = (dr.vimext.SanProviderDatastoreLocator) {
[#2]             dynamicType = <unset>,
[#2]             primaryUrl = "sanfs://vmfs_uuid:49adfee5-d396480b-e747-00151793960d/",
[#2]          },
[#2]          reason = (vmodl.MethodFault) null,
[#2]          msg = ""
[#2]       },
[#2]    },
[#2]    (dr.secondary.ReplicationManager.SingleVmFailure) {
[#2]       dynamicType = <unset>,
[#2]       vm = 'dr.secondary.ShadowVm:shadow-vm-10379',
[#2]       fault = (dr.san.fault.RecoveredDatastoreNotFound) {
[#2]          dynamicType = <unset>,
[#2]          datastore = (dr.vimext.SanProviderDatastoreLocator) {
[#2]             dynamicType = <unset>,
[#2]             primaryUrl = "sanfs://vmfs_uuid:49adfee5-d396480b-e747-00151793960d/",
[#2]          },
[#2]          reason = (vmodl.MethodFault) null,
[#2]          msg = ""
[#2]       },
[#2]    }
[#2] ]
[2009-03-12 08:44:10.932 'BeginImageTest-Task' 2808 info] State set to success
[2009-03-12 08:44:10.932 'SecondaryReplication' 2808 verbose] Changing recovery state of 'shadow-group-4245' to 'testing'
[2009-03-12 08:44:10.932 'SecondaryReplication' 2808 verbose] Saving ShadowGroup to DB object
[2009-03-12 08:44:10.932 'RSStorageOperation-10555-Task' 2832 verbose] Progress advanced to 85
[2009-03-12 08:44:10.932 'RSStorageOperationList-10554-Task' 2840 info] MRT-Progress Task RSStorageOperation-10555-75 for dr.secondary.RecoveryStep:RSStorageOperation-10555 85
[2009-03-12 08:44:10.932 'RSStorageOperationList-10554-Task' 2840 verbose] Progress advanced to 85
[2009-03-12 08:44:10.932 'RootStepList-10541-Task' 2836 info] MRT-Progress Task RSStorageOperationList-10554-73 for dr.secondary.RecoveryStep:RSStorageOperationList-10554 85
[2009-03-12 08:44:10.932 'RootStepList-10541-Task' 2836 verbose] Progress advanced to 7
[2009-03-12 08:44:10.948 'RecoveryContext-70-Task' 2812 verbose] Progress advanced to 7
[2009-03-12 08:44:10.948 'SecondarySanProvider' 2808 trivia] 'Prepare 1 groups for test' took 87.901 seconds
[2009-03-12 08:44:10.948 'SecondarySanProvider' 2808 trivia] Firing CallOnDestruction callback
[2009-03-12 08:44:10.948 'SanConfigManager' 2808 trivia] Scheduling lun group computation in 0 seconds
[2009-03-12 08:44:10.948 'RSStorageOperation-10555-Task' 2832 verbose] Progress advanced to 90
[2009-03-12 08:44:10.948 'RSStorageOperationList-10554-Task' 2808 info] MRT-Progress Task RSStorageOperation-10555-75 for dr.secondary.RecoveryStep:RSStorageOperation-10555 90
[2009-03-12 08:44:10.948 'RSStorageOperationList-10554-Task' 2808 verbose] Progress advanced to 90
[2009-03-12 08:44:10.948 'RootStepList-10541-Task' 2808 info] MRT-Progress Task RSStorageOperationList-10554-73 for dr.secondary.RecoveryStep:RSStorageOperationList-10554 90
[2009-03-12 08:44:10.948 'RootStepList-10541-Task' 2808 verbose] Progress advanced to 8
[2009-03-12 08:44:10.948 'RecoveryContext-70-Task' 2808 verbose] Progress advanced to 8
[2009-03-12 08:44:10.948 'RSStorageOperation-10555-Task' 2832 verbose] Result set to (dr.secondary.ReplicationManager.SingleVmFailure) [
[#2]    (dr.secondary.ReplicationManager.SingleVmFailure) {
[#2]       dynamicType = <unset>,
[#2]       vm = 'dr.secondary.ShadowVm:shadow-vm-10300',
[#2]       fault = (dr.san.fault.RecoveredDatastoreNotFound) {
[#2]          dynamicType = <unset>,
[#2]          datastore = (dr.vimext.SanProviderDatastoreLocator) {
[#2]             dynamicType = <unset>,
[#2]             primaryUrl = "sanfs://vmfs_uuid:49adfee5-d396480b-e747-00151793960d/",
[#2]          },
[#2]          reason = (vmodl.MethodFault) null,
[#2]          msg = ""
[#2]       },
[#2]    },
[#2]    (dr.secondary.ReplicationManager.SingleVmFailure) {
[#2]       dynamicType = <unset>,
[#2]       vm = 'dr.secondary.ShadowVm:shadow-vm-10379',
[#2]       fault = (dr.san.fault.RecoveredDatastoreNotFound) {
[#2]          dynamicType = <unset>,
[#2]          datastore = (dr.vimext.SanProviderDatastoreLocator) {
[#2]             dynamicType = <unset>,
[#2]             primaryUrl = "sanfs://vmfs_uuid:49adfee5-d396480b-e747-00151793960d/",
[#2]          },
[#2]          reason = (vmodl.MethodFault) null,
[#2]          msg = ""
[#2]       },
[#2]    }
[#2] ]
[2009-03-12 08:44:10.948 'RSStorageOperation-10555-Task' 2832 info] State set to success
[2009-03-12 08:44:10.948 'RSStorageOperationList-10554-Task' 2804 info] MRT-DoneCallback Task RSStorageOperation-10555-75 for RSStorageOperation-10555 [success]
[2009-03-12 08:44:10.963 'RSStorageOperation-10555' 2804 info] [RSStorageOperation-10555] SetTaskComplete
[2009-03-12 08:44:10.963 'RSStorageOperation-10555' 2804 info] SetRuntimeStatus for RSStorageOperation-10555 from running to success
[2009-03-12 08:44:10.978 'RSStorageOperationList-10554-Task' 2804 verbose] Progress advanced to 100
[2009-03-12 08:44:10.978 'RSStorageOperationList-10554-Task' 2804 info] State set to success
[2009-03-12 08:44:10.978 'RSStorageOperationList-10554-Task' 2804 info] Not Starting Tasks All Tasks Complete
[2009-03-12 08:44:10.978 'RSStorageOperation-10555-Task' 2804 verbose] Task destroyed
[2009-03-12 08:44:10.978 'RootStepList-10541-Task' 2804 info] MRT-Progress Task RSStorageOperationList-10554-73 for dr.secondary.RecoveryStep:RSStorageOperationList-10554 100
[2009-03-12 08:44:10.978 'RootStepList-10541-Task' 2804 verbose] Progress advanced to 9
[2009-03-12 08:44:10.978 'RootStepList-10541-Task' 2804 info] MRT-DoneCallback Task RSStorageOperationList-10554-73 for RSStorageOperationList-10554 [success]
[2009-03-12 08:44:10.978 'RecoveryContext-70-Task' 2808 verbose] Progress advanced to 9
[2009-03-12 08:44:10.978 'SanConfigManager' 2808 trivia] Recomputing lun groups
[2009-03-12 08:44:10.978 'RSStorageOperationList-10554' 2804 info] StorageTask with VM (0) shadow-vm-10300 had fault (dr.san.fault.RecoveredDatastoreNotFound) {
[#2]    dynamicType = <unset>,
[#2]    datastore = (dr.vimext.SanProviderDatastoreLocator) {
[#2]       dynamicType = <unset>,
[#2]       primaryUrl = "sanfs://vmfs_uuid:49adfee5-d396480b-e747-00151793960d/",
[#2]    },
[#2]    reason = (vmodl.MethodFault) null,
[#2]    msg = ""
[#2] }
[2009-03-12 08:44:10.994 'SanConfigManager' 2808 trivia] 'Retrieved 1 properties of 1 objects of type 'vim.Datastore'' took 0.015 seconds
[2009-03-12 08:44:10.994 'RSStorageOperationList-10554' 2804 info] StorageTask with VM (1) shadow-vm-10379 had fault (dr.san.fault.RecoveredDatastoreNotFound) {
[#2]    dynamicType = <unset>,
[#2]    datastore = (dr.vimext.SanProviderDatastoreLocator) {
[#2]       dynamicType = <unset>,
[#2]       primaryUrl = "sanfs://vmfs_uuid:49adfee5-d396480b-e747-00151793960d/",
[#2]    },
[#2]    reason = (vmodl.MethodFault) null,
[#2]    msg = ""
[#2] }
[2009-03-12 08:44:11.009 'SanConfigManager' 2808 trivia] Found 1 properties for object 'vim.ComputeResource:domain-s556'
[2009-03-12 08:44:11.009 'SanConfigManager' 2808 trivia] Found 1 properties for object 'vim.ComputeResource:domain-s591'
[2009-03-12 08:44:11.009 'SanConfigManager' 2808 verbose] Found 2 hosts for 1 datastores ('datastore-994',..)
[2009-03-12 08:44:11.009 'RSStorageOperationList-10554' 2804 warning] StorageTask All VMs failed.
[2009-03-12 08:44:11.009 'RSStorageOperationList-10554' 2804 info] [RSStorageOperationList-10554] SetTaskComplete
[2009-03-12 08:44:11.009 'RSStorageOperationList-10554' 2804 info] SetRuntimeStatus for RSStorageOperationList-10554 from running to success
[2009-03-12 08:44:11.086 'RSGroup-10556SecondaryRunningVMSuspend-Task' 2804 verbose] Task created
[2009-03-12 08:44:11.086 'SanConfigManager' 2808 verbose] Refreshing storage on host 'host-559'
[2009-03-12 08:44:11.086 'SanProvider.RefreshStorage-Task' 2808 verbose] Task created
[2009-03-12 08:44:11.086 'SimpleTaskManager' 2808 verbose] Adding task SanProvider.RefreshStorage-79
[2009-03-12 08:44:11.086 'SanProvider.RefreshStorage-Task' 2808 info] State set to running
[2009-03-12 08:44:11.086 'SanProvider.RefreshStorage-Task' 2808 verbose] Scheduling work item
[2009-03-12 08:44:11.086 'SanProvider.RefreshStorage-Task' 2812 info] Running work method
[2009-03-12 08:44:11.086 'SanConfigManager' 2808 verbose] Refreshing storage on host 'host-594'
[2009-03-12 08:44:11.086 'SanProvider.RefreshStorage-Task' 2808 verbose] Task created
[2009-03-12 08:44:11.086 'SimpleTaskManager' 2808 verbose] Adding task SanProvider.RefreshStorage-80
[2009-03-12 08:44:11.086 'SanProvider.RefreshStorage-Task' 2808 info] State set to running
[2009-03-12 08:44:11.086 'SanProvider.RefreshStorage-Task' 2808 verbose] Scheduling work item
[2009-03-12 08:44:11.086 'SanProvider.RefreshStorage-Task' 2840 info] Running work method
[2009-03-12 08:44:11.086 'SanConfigManager' 2808 trivia] MLTW, handling task progress
[2009-03-12 08:44:11.086 'SanConfigManager' 2808 trivia] MLTW, handling task state
[2009-03-12 08:44:11.086 'SanConfigManager' 2808 trivia] MLTW, handling task progress
[2009-03-12 08:44:11.086 'SanConfigManager' 2808 trivia] MLTW, handling task state
[2009-03-12 08:44:11.101 'RootStepList-10541-Task' 2804 info] Starting Task RSGroup-10556SecondaryRunningVMSuspend-78 for step RSGroup-10556
[2009-03-12 08:44:11.101 'RootStepList-10541-Task' 2804 verbose] MultipleRecoveryTask Info max 1 cur 1 remain 8
[2009-03-12 08:44:11.101 'RSStorageOperationList-10554-Task' 2804 verbose] Task destroyed
[2009-03-12 08:44:11.101 'RSGroup-10556SecondaryRunningVMSuspend-Task' 2804 info] State set to running
[2009-03-12 08:44:11.101 'RSGroup-10556SecondaryRunningVMSuspend-Task' 2804 verbose] Scheduling work item
[2009-03-12 08:44:11.101 'RootStepList-10541-Task' 2804 info] MRT-Progress Task RSGroup-10556SecondaryRunningVMSuspend-78 for dr.secondary.RecoveryStep:RSGroup-10556 0
[2009-03-12 08:44:11.101 'RootStepList-10541-Task' 2804 verbose] Progress is unchanged
[2009-03-12 08:44:11.101 'RSGroup-10556SecondaryRunningVMSuspend-Task' 2804 info] Running work method
[2009-03-12 08:44:11.101 'RSGroup-10556' 2804 info] SetRuntimeStatus for RSGroup-10556 from queued to running
[2009-03-12 08:44:11.101 'RSGroup-10556' 2804 info] Entering RecoveryStepGroup::StepPerform
[2009-03-12 08:44:11.101 'RSGroup-10556SecondaryRunningVMSuspend-Task' 2804 info] MultipleRecoveryTask Nothing to do - exiting.
[2009-03-12 08:44:11.101 'RSGroup-10556SecondaryRunningVMSuspend-Task' 2804 info] Work function completed successfully
[2009-03-12 08:44:11.101 'RSGroup-10556SecondaryRunningVMSuspend-Task' 2804 info] State set to success
[2009-03-12 08:44:11.101 'RootStepList-10541-Task' 2804 info] MRT-DoneCallback Task RSGroup-10556SecondaryRunningVMSuspend-78 for RSGroup-10556 [success]
[2009-03-12 08:44:11.101 'RSGroup-10556' 2804 info] [RSGroup-10556] SetTaskComplete
[2009-03-12 08:44:11.101 'RSGroup-10556' 2804 info] SetRuntimeStatus for RSGroup-10556 from running to success
[2009-03-12 08:44:11.117 'RSGroup-10557SecondaryShadowVMRecover-Task' 2804 verbose] Task created
[2009-03-12 08:44:11.132 'RootStepList-10541-Task' 2804 info] Starting Task RSGroup-10557SecondaryShadowVMRecover-81 for step RSGroup-10557
[2009-03-12 08:44:11.132 'RootStepList-10541-Task' 2804 verbose] MultipleRecoveryTask Info max 1 cur 1 remain 7
[2009-03-12 08:44:11.132 'RSGroup-10556SecondaryRunningVMSuspend-Task' 2804 verbose] Task destroyed
[2009-03-12 08:44:11.132 'RSGroup-10557SecondaryShadowVMRecover-Task' 2804 info] State set to running
[2009-03-12 08:44:11.132 'RSGroup-10557SecondaryShadowVMRecover-Task' 2804 verbose] Scheduling work item
[2009-03-12 08:44:11.147 'RootStepList-10541-Task' 2804 info] MRT-Progress Task RSGroup-10557SecondaryShadowVMRecover-81 for dr.secondary.RecoveryStep:RSGroup-10557 0
[2009-03-12 08:44:11.147 'RootStepList-10541-Task' 2804 verbose] Progress advanced to 18
[2009-03-12 08:44:11.147 'RSGroup-10557SecondaryShadowVMRecover-Task' 2804 info] Running work method
[2009-03-12 08:44:11.147 'RSGroup-10557' 2804 info] SetRuntimeStatus for RSGroup-10557 from queued to running
[2009-03-12 08:44:11.147 'RecoveryContext-70-Task' 2820 verbose] Progress advanced to 18
[2009-03-12 08:44:11.147 'RSGroup-10557' 2804 info] Entering RecoveryStepGroup::StepPerform
[2009-03-12 08:44:11.147 'RSVm-10558-Task' 2804 verbose] Task created
[2009-03-12 08:44:11.163 'RSGroup-10557SecondaryShadowVMRecover-Task' 2804 info] Starting Task RSVm-10558-82 for step RSVm-10558
[2009-03-12 08:44:11.163 'RSGroup-10557SecondaryShadowVMRecover-Task' 2804 verbose] MultipleRecoveryTask Info max 1 cur 1 remain 0
[2009-03-12 08:44:11.163 'RSVm-10558-Task' 2804 info] State set to running
[2009-03-12 08:44:11.163 'RSVm-10558-Task' 2804 verbose] Scheduling work item
[2009-03-12 08:44:11.163 'RSGroup-10557SecondaryShadowVMRecover-Task' 2804 info] Not Starting Tasks MaxNumRunningTasks
[2009-03-12 08:44:11.163 'RSGroup-10557SecondaryShadowVMRecover-Task' 2804 info] Work function yielded
[2009-03-12 08:44:11.163 'RSGroup-10557SecondaryShadowVMRecover-Task' 2804 info] MRT-Progress Task RSVm-10558-82 for dr.secondary.RecoveryStep:RSVm-10558 0
[2009-03-12 08:44:11.163 'RSGroup-10557SecondaryShadowVMRecover-Task' 2804 verbose] Progress is unchanged
[2009-03-12 08:44:11.163 'RSVm-10558-Task' 2804 info] Running work method
[2009-03-12 08:44:11.163 'RSVm-10558' 2804 info] SetRuntimeStatus for RSVm-10558 from queued to running
[2009-03-12 08:44:11.163 'RSVm-10558' 2804 info] [RSVm-10558], shadow-vm-10379 in known bad list. Cancelling
[2009-03-12 08:44:11.163 'RSVm-10558-Task' 2804 verbose] Progress advanced to 100
[2009-03-12 08:44:11.163 'RSVm-10558-Task' 2804 verbose] Error set to (dr.san.fault.RecoveredDatastoreNotFound) {
[#2]    dynamicType = <unset>,
[#2]    datastore = (dr.vimext.SanProviderDatastoreLocator) {
[#2]       dynamicType = <unset>,
[#2]       primaryUrl = "sanfs://vmfs_uuid:49adfee5-d396480b-e747-00151793960d/",
[#2]    },
[#2]    reason = (vmodl.MethodFault) null,
[#2]    msg = ""
[#2] }
[2009-03-12 08:44:11.163 'RSVm-10558-Task' 2804 info] State set to error
[2009-03-12 08:44:11.163 'RSVm-10558-Task' 2804 info] MultipleRecoveryTask Parent Task Canceling.
[2009-03-12 08:44:11.163 'RSVm-10558' 2804 info] StepCancel RSVm-10558 Try to Cancel Step while _task state is error
[2009-03-12 08:44:11.163 'RSVm-10558-Task' 2804 info] Work function completed with error
[2009-03-12 08:44:11.163 'RSGroup-10557SecondaryShadowVMRecover-Task' 2804 info] MRT-Progress Task RSVm-10558-82 for dr.secondary.RecoveryStep:RSVm-10558 100
[2009-03-12 08:44:11.163 'RSGroup-10557SecondaryShadowVMRecover-Task' 2804 verbose] Progress advanced to 100
[2009-03-12 08:44:11.163 'RSGroup-10557SecondaryShadowVMRecover-Task' 2804 info] MRT-DoneCallback Task RSVm-10558-82 for RSVm-10558 [error]
[2009-03-12 08:44:11.178 'RSVm-10558' 2804 info] [RSVm-10558] SetTaskComplete
[2009-03-12 08:44:11.178 'RSVm-10558' 2804 info] SetRuntimeStatus for RSVm-10558 from running to error
[2009-03-12 08:44:11.178 'RSVm-10558' 2804 info] RuntimeInfoError (dr.san.fault.RecoveredDatastoreNotFound) {
[#2]    dynamicType = <unset>,
[#2]    datastore = (dr.vimext.SanProviderDatastoreLocator) {
[#2]       dynamicType = <unset>,
[#2]       primaryUrl = "sanfs://vmfs_uuid:49adfee5-d396480b-e747-00151793960d/",
[#2]    },
[#2]    reason = (vmodl.MethodFault) null,
[#2]    msg = ""
[#2] }
[2009-03-12 08:44:11.178 'RootStepList-10541-Task' 2820 info] MRT-Progress Task RSGroup-10557SecondaryShadowVMRecover-81 for dr.secondary.RecoveryStep:RSGroup-10557 100
[2009-03-12 08:44:11.178 'RootStepList-10541-Task' 2820 verbose] Progress advanced to 27
[2009-03-12 08:44:11.178 'RecoveryContext-70-Task' 2820 verbose] Progress advanced to 27
[2009-03-12 08:44:11.178 'RSGroup-10557SecondaryShadowVMRecover-Task' 2804 verbose] Progress is unchanged
[2009-03-12 08:44:11.178 'RSGroup-10557SecondaryShadowVMRecover-Task' 2804 verbose] Error set to (dr.san.fault.RecoveredDatastoreNotFound) {
[#2]    dynamicType = <unset>,
[#2]    datastore = (dr.vimext.SanProviderDatastoreLocator) {
[#2]       dynamicType = <unset>,
[#2]       primaryUrl = "sanfs://vmfs_uuid:49adfee5-d396480b-e747-00151793960d/",
[#2]    },
[#2]    reason = (vmodl.MethodFault) null,
[#2]    msg = ""
[#2] }
[2009-03-12 08:44:11.178 'RSGroup-10557SecondaryShadowVMRecover-Task' 2804 info] State set to error
[2009-03-12 08:44:11.178 'RSGroup-10557SecondaryShadowVMRecover-Task' 2804 info] Not Starting Tasks All Tasks Complete
[2009-03-12 08:44:11.178 'RSVm-10558-Task' 2804 verbose] Task destroyed
[2009-03-12 08:44:11.178 'RootStepList-10541-Task' 2804 info] MRT-DoneCallback Task RSGroup-10557SecondaryShadowVMRecover-81 for RSGroup-10557 [error]
[2009-03-12 08:44:11.178 'RSGroup-10557' 2804 info] [RSGroup-10557] SetTaskComplete
[2009-03-12 08:44:11.178 'RSGroup-10557' 2804 info] SetRuntimeStatus for RSGroup-10557 from running to error
[2009-03-12 08:44:11.178 'RSGroup-10557' 2804 info] RuntimeInfoError (dr.san.fault.RecoveredDatastoreNotFound) {
[#2]    dynamicType = <unset>,
[#2]    datastore = (dr.vimext.SanProviderDatastoreLocator) {
[#2]       dynamicType = <unset>,
[#2]       primaryUrl = "sanfs://vmfs_uuid:49adfee5-d396480b-e747-00151793960d/",
[#2]    },
[#2]    reason = (vmodl.MethodFault) null,
[#2]    msg = ""
[#2] }
[2009-03-12 08:44:11.178 'RSGroup-10582SecondaryShadowVMRecover-Task' 2804 verbose] Task created
[2009-03-12 08:44:11.193 'RootStepList-10541-Task' 2804 info] Starting Task RSGroup-10582SecondaryShadowVMRecover-83 for step RSGroup-10582
[2009-03-12 08:44:11.193 'RootStepList-10541-Task' 2804 verbose] MultipleRecoveryTask Info max 1 cur 1 remain 6
[2009-03-12 08:44:11.193 'RSGroup-10557SecondaryShadowVMRecover-Task' 2804 verbose] Task destroyed
[2009-03-12 08:44:11.193 'RSGroup-10582SecondaryShadowVMRecover-Task' 2804 info] State set to running
[2009-03-12 08:44:11.193 'RSGroup-10582SecondaryShadowVMRecover-Task' 2804 verbose] Scheduling work item
[2009-03-12 08:44:11.193 'RootStepList-10541-Task' 2804 info] MRT-Progress Task RSGroup-10582SecondaryShadowVMRecover-83 for dr.secondary.RecoveryStep:RSGroup-10582 0
[2009-03-12 08:44:11.193 'RootStepList-10541-Task' 2804 verbose] Progress is unchanged
[2009-03-12 08:44:11.193 'RSGroup-10582SecondaryShadowVMRecover-Task' 2804 info] Running work method
[2009-03-12 08:44:11.193 'RSGroup-10582' 2804 info] SetRuntimeStatus for RSGroup-10582 from queued to running
[2009-03-12 08:44:11.193 'RSGroup-10582' 2804 info] Entering RecoveryStepGroup::StepPerform
[2009-03-12 08:44:11.193 'RSVm-10583-Task' 2804 verbose] Task created
[2009-03-12 08:44:11.193 'RSGroup-10582SecondaryShadowVMRecover-Task' 2804 info] Starting Task RSVm-10583-84 for step RSVm-10583
[2009-03-12 08:44:11.193 'RSGroup-10582SecondaryShadowVMRecover-Task' 2804 verbose] MultipleRecoveryTask Info max 500 cur 1 remain 0
[2009-03-12 08:44:11.193 'RSVm-10583-Task' 2804 info] State set to running
[2009-03-12 08:44:11.193 'RSVm-10583-Task' 2804 verbose] Scheduling work item
[2009-03-12 08:44:11.193 'RSGroup-10582SecondaryShadowVMRecover-Task' 2804 info] Not Starting Tasks All Tasks Running
[2009-03-12 08:44:11.193 'RSGroup-10582SecondaryShadowVMRecover-Task' 2804 info] Work function yielded
[2009-03-12 08:44:11.193 'RSGroup-10582SecondaryShadowVMRecover-Task' 2804 info] MRT-Progress Task RSVm-10583-84 for dr.secondary.RecoveryStep:RSVm-10583 0
[2009-03-12 08:44:11.193 'RSGroup-10582SecondaryShadowVMRecover-Task' 2804 verbose] Progress is unchanged
[2009-03-12 08:44:11.209 'RSVm-10583-Task' 2804 info] Running work method
[2009-03-12 08:44:11.209 'RSVm-10583' 2804 info] SetRuntimeStatus for RSVm-10583 from queued to running
[2009-03-12 08:44:11.209 'RSVm-10583' 2804 info] [RSVm-10583], shadow-vm-10300 in known bad list. Cancelling
[2009-03-12 08:44:11.209 'RSVm-10583-Task' 2804 verbose] Progress advanced to 100
[2009-03-12 08:44:11.209 'RSVm-10583-Task' 2804 verbose] Error set to (dr.san.fault.RecoveredDatastoreNotFound) {
[#2]    dynamicType = <unset>,
[#2]    datastore = (dr.vimext.SanProviderDatastoreLocator) {
[#2]       dynamicType = <unset>,
[#2]       primaryUrl = "sanfs://vmfs_uuid:49adfee5-d396480b-e747-00151793960d/",
[#2]    },
[#2]    reason = (vmodl.MethodFault) null,
[#2]    msg = ""
[#2] }
[2009-03-12 08:44:11.209 'RSVm-10583-Task' 2804 info] State set to error
[2009-03-12 08:44:11.209 'RSVm-10583-Task' 2804 info] MultipleRecoveryTask Parent Task Canceling.
[2009-03-12 08:44:11.209 'RSVm-10583' 2804 info] StepCancel RSVm-10583 Try to Cancel Step while _task state is error
[2009-03-12 08:44:11.209 'RSVm-10583-Task' 2804 info] Work function completed with error
[2009-03-12 08:44:11.209 'RSGroup-10582SecondaryShadowVMRecover-Task' 2804 info] MRT-Progress Task RSVm-10583-84 for dr.secondary.RecoveryStep:RSVm-10583 100
[2009-03-12 08:44:11.209 'RSGroup-10582SecondaryShadowVMRecover-Task' 2804 verbose] Progress advanced to 100
[2009-03-12 08:44:11.209 'RSGroup-10582SecondaryShadowVMRecover-Task' 2804 info] MRT-DoneCallback Task RSVm-10583-84 for RSVm-10583 [error]
[2009-03-12 08:44:11.209 'RSVm-10583' 2804 info] [RSVm-10583] SetTaskComplete
[2009-03-12 08:44:11.209 'RSVm-10583' 2804 info] SetRuntimeStatus for RSVm-10583 from running to error
[2009-03-12 08:44:11.209 'RSVm-10583' 2804 info] RuntimeInfoError (dr.san.fault.RecoveredDatastoreNotFound) {
[#2]    dynamicType = <unset>,
[#2]    datastore = (dr.vimext.SanProviderDatastoreLocator) {
[#2]       dynamicType = <unset>,
[#2]       primaryUrl = "sanfs://vmfs_uuid:49adfee5-d396480b-e747-00151793960d/",
[#2]    },
[#2]    reason = (vmodl.MethodFault) null,
[#2]    msg = ""
[#2] }
[2009-03-12 08:44:11.209 'RootStepList-10541-Task' 2832 info] MRT-Progress Task RSGroup-10582SecondaryShadowVMRecover-83 for dr.secondary.RecoveryStep:RSGroup-10582 100
[2009-03-12 08:44:11.209 'RootStepList-10541-Task' 2832 verbose] Progress advanced to 36
[2009-03-12 08:44:11.209 'RecoveryContext-70-Task' 2776 verbose] Progress advanced to 36
[2009-03-12 08:44:11.209 'RSGroup-10582SecondaryShadowVMRecover-Task' 2804 verbose] Progress is unchanged
[2009-03-12 08:44:11.209 'RSGroup-10582SecondaryShadowVMRecover-Task' 2804 verbose] Error set to (dr.san.fault.RecoveredDatastoreNotFound) {
[#2]    dynamicType = <unset>,
[#2]    datastore = (dr.vimext.SanProviderDatastoreLocator) {
[#2]       dynamicType = <unset>,
[#2]       primaryUrl = "sanfs://vmfs_uuid:49adfee5-d396480b-e747-00151793960d/",
[#2]    },
[#2]    reason = (vmodl.MethodFault) null,
[#2]    msg = ""
[#2] }
[2009-03-12 08:44:11.209 'RSGroup-10582SecondaryShadowVMRecover-Task' 2804 info] State set to error
[2009-03-12 08:44:11.209 'RSGroup-10582SecondaryShadowVMRecover-Task' 2804 info] Not Starting Tasks All Tasks Complete
[2009-03-12 08:44:11.209 'RSVm-10583-Task' 2804 verbose] Task destroyed
[2009-03-12 08:44:11.209 'RootStepList-10541-Task' 2832 info] MRT-DoneCallback Task RSGroup-10582SecondaryShadowVMRecover-83 for RSGroup-10582 [error]
[2009-03-12 08:44:11.209 'RSGroup-10582' 2832 info] [RSGroup-10582] SetTaskComplete
[2009-03-12 08:44:11.209 'RSGroup-10582' 2832 info] SetRuntimeStatus for RSGroup-10582 from running to error
[2009-03-12 08:44:11.209 'RSGroup-10582' 2832 info] RuntimeInfoError (dr.san.fault.RecoveredDatastoreNotFound) {
[#2]    dynamicType = <unset>,
[#2]    datastore = (dr.vimext.SanProviderDatastoreLocator) {
[#2]       dynamicType = <unset>,
[#2]       primaryUrl = "sanfs://vmfs_uuid:49adfee5-d396480b-e747-00151793960d/",
[#2]    },
[#2]    reason = (vmodl.MethodFault) null,
[#2]    msg = ""
[#2] }
[2009-03-12 08:44:11.209 'RSGroup-10607SecondaryShadowVMRecover-Task' 2832 verbose] Task created
[2009-03-12 08:44:11.224 'RootStepList-10541-Task' 2832 info] Starting Task RSGroup-10607SecondaryShadowVMRecover-85 for step RSGroup-10607
[2009-03-12 08:44:11.224 'RootStepList-10541-Task' 2832 verbose] MultipleRecoveryTask Info max 1 cur 1 remain 5
[2009-03-12 08:44:11.224 'RSGroup-10582SecondaryShadowVMRecover-Task' 2832 verbose] Task destroyed
[2009-03-12 08:44:11.224 'RSGroup-10607SecondaryShadowVMRecover-Task' 2832 info] State set to running
[2009-03-12 08:44:11.224 'RSGroup-10607SecondaryShadowVMRecover-Task' 2832 verbose] Scheduling work item
[2009-03-12 08:44:11.224 'RSGroup-10607SecondaryShadowVMRecover-Task' 2836 info] Running work method
[2009-03-12 08:44:11.224 'RSGroup-10607' 2836 info] SetRuntimeStatus for RSGroup-10607 from queued to running
[2009-03-12 08:44:11.224 'RootStepList-10541-Task' 2832 info] MRT-Progress Task RSGroup-10607SecondaryShadowVMRecover-85 for dr.secondary.RecoveryStep:RSGroup-10607 0
[2009-03-12 08:44:11.224 'RSGroup-10607' 2836 info] Entering RecoveryStepGroup::StepPerform
[2009-03-12 08:44:11.224 'RSGroup-10607SecondaryShadowVMRecover-Task' 2836 info] MultipleRecoveryTask Nothing to do - exiting.
[2009-03-12 08:44:11.224 'RSGroup-10607SecondaryShadowVMRecover-Task' 2836 info] Work function completed successfully
[2009-03-12 08:44:11.224 'RSGroup-10607SecondaryShadowVMRecover-Task' 2836 info] State set to success
[2009-03-12 08:44:11.224 'RootStepList-10541-Task' 2832 verbose] Progress is unchanged
[2009-03-12 08:44:11.224 'RootStepList-10541-Task' 2832 info] MRT-DoneCallback Task RSGroup-10607SecondaryShadowVMRecover-85 for RSGroup-10607 [success]
[2009-03-12 08:44:11.224 'RSGroup-10607' 2832 info] [RSGroup-10607] SetTaskComplete
[2009-03-12 08:44:11.224 'RSGroup-10607' 2832 info] SetRuntimeStatus for RSGroup-10607 from running to success
[2009-03-12 08:44:11.224 'RSGroup-10608SecondaryShadowVMRecover-Task' 2832 verbose] Task created
[2009-03-12 08:44:11.240 'RootStepList-10541-Task' 2832 info] Starting Task RSGroup-10608SecondaryShadowVMRecover-86 for step RSGroup-10608
[2009-03-12 08:44:11.240 'RootStepList-10541-Task' 2832 verbose] MultipleRecoveryTask Info max 1 cur 1 remain 4
[2009-03-12 08:44:11.240 'RSGroup-10607SecondaryShadowVMRecover-Task' 2832 verbose] Task destroyed
[2009-03-12 08:44:11.240 'RSGroup-10608SecondaryShadowVMRecover-Task' 2832 info] State set to running
[2009-03-12 08:44:11.240 'RSGroup-10608SecondaryShadowVMRecover-Task' 2832 verbose] Scheduling work item
[2009-03-12 08:44:11.240 'RSGroup-10608SecondaryShadowVMRecover-Task' 2836 info] Running work method
[2009-03-12 08:44:11.240 'RSGroup-10608' 2836 info] SetRuntimeStatus for RSGroup-10608 from queued to running
[2009-03-12 08:44:11.240 'RootStepList-10541-Task' 2832 info] MRT-Progress Task RSGroup-10608SecondaryShadowVMRecover-86 for dr.secondary.RecoveryStep:RSGroup-10608 0
[2009-03-12 08:44:11.240 'RSGroup-10608' 2836 info] Entering RecoveryStepGroup::StepPerform
[2009-03-12 08:44:11.240 'RSGroup-10608SecondaryShadowVMRecover-Task' 2836 info] MultipleRecoveryTask Nothing to do - exiting.
[2009-03-12 08:44:11.240 'RSGroup-10608SecondaryShadowVMRecover-Task' 2836 info] Work function completed successfully
[2009-03-12 08:44:11.240 'RSGroup-10608SecondaryShadowVMRecover-Task' 2836 info] State set to success
[2009-03-12 08:44:11.240 'RootStepList-10541-Task' 2832 verbose] Progress advanced to 45
[2009-03-12 08:44:11.240 'RecoveryContext-70-Task' 2776 verbose] Progress advanced to 45
[2009-03-12 08:44:11.240 'RootStepList-10541-Task' 2832 info] MRT-DoneCallback Task RSGroup-10608SecondaryShadowVMRecover-86 for RSGroup-10608 [success]
[2009-03-12 08:44:11.240 'RSGroup-10608' 2832 info] [RSGroup-10608] SetTaskComplete
[2009-03-12 08:44:11.240 'RSGroup-10608' 2832 info] SetRuntimeStatus for RSGroup-10608 from running to success
[2009-03-12 08:44:11.255 'RSCalloutPrompt-10609-Task' 2832 verbose] Task created
[2009-03-12 08:44:12.054 'Locale' 2788 warning] FormatField: Optional unset (dr.san.fault.RecoveredDatastoreNotFound.reason)
[2009-03-12 08:44:12.054 'Locale' 2788 warning] FormatField: Optional unset (dr.san.fault.RecoveredDatastoreNotFound.reason)
[2009-03-12 08:44:12.054 'Locale' 2788 warning] FormatField: Optional unset (dr.san.fault.RecoveredDatastoreNotFound.reason)
[2009-03-12 08:44:12.054 'Locale' 2788 warning] FormatField: Optional unset (dr.san.fault.RecoveredDatastoreNotFound.reason)
[2009-03-12 08:44:12.591 'RootStepList-10541-Task' 2832 info] Starting Task RSCalloutPrompt-10609-87 for step RSCalloutPrompt-10609
[2009-03-12 08:44:12.591 'RootStepList-10541-Task' 2832 verbose] MultipleRecoveryTask Info max 1 cur 1 remain 3
[2009-03-12 08:44:12.591 'RSGroup-10608SecondaryShadowVMRecover-Task' 2832 verbose] Task destroyed
[2009-03-12 08:44:12.591 'RSCalloutPrompt-10609-Task' 2832 info] State set to running
[2009-03-12 08:44:12.591 'RSCalloutPrompt-10609-Task' 2832 verbose] Scheduling work item
[2009-03-12 08:44:12.591 'RSCalloutPrompt-10609-Task' 2836 info] Running work method
[2009-03-12 08:44:12.591 'RSCalloutPrompt-10609' 2836 info] SetRuntimeStatus for RSCalloutPrompt-10609 from queued to running
[2009-03-12 08:44:12.591 'RootStepList-10541-Task' 2832 info] MRT-Progress Task RSCalloutPrompt-10609-87 for dr.secondary.RecoveryStep:RSCalloutPrompt-10609 0
[2009-03-12 08:44:12.591 'RSCalloutPrompt-10609-Task' 2836 info] Work function yielded
[2009-03-12 08:44:12.591 'RecoveryContext-70-Task' 2836 verbose] GetState returned running
[2009-03-12 08:44:12.591 'RootStepList-10541-Task' 2832 verbose] Progress advanced to 54
[2009-03-12 08:44:12.607 'RecoveryContext-70-Task' 2836 verbose] Progress advanced to 54
[2009-03-12 08:44:13.037 'RecoveryContext-70-Task' 2788 verbose] GetState returned running
[2009-03-12 08:44:15.710 'SanProvider.RefreshStorage-Task' 2840 info] Work function completed successfully
[2009-03-12 08:44:15.710 'SanProvider.RefreshStorage-Task' 2840 info] State set to success
[2009-03-12 08:44:15.710 'SanConfigManager' 2840 trivia] MLTW, handling task state
[2009-03-12 08:44:15.710 'SanConfigManager' 2840 trivia] MLTW, number of active tasks set to 1
[2009-03-12 08:44:19.656 'SanProvider.RefreshStorage-Task' 2812 info] Work function completed successfully
[2009-03-12 08:44:19.656 'SanProvider.RefreshStorage-Task' 2812 info] State set to success
[2009-03-12 08:44:19.656 'SanConfigManager' 2812 trivia] MLTW, handling task state
[2009-03-12 08:44:19.656 'SanConfigManager' 2812 trivia] MLTW, number of active tasks set to 0
[2009-03-12 08:44:19.656 'SanConfigManager' 2808 trivia] MLTW completed, woken up
[2009-03-12 08:44:26.524 'RSCalloutPrompt-10609' 2636 info] [RSCalloutPrompt-10609] Received NotifyTaskOfUserResponse
[2009-03-12 08:44:26.524 'RSCalloutPrompt-10609-Task' 2636 info] State set to success
[2009-03-12 08:44:26.524 'RootStepList-10541-Task' 2820 info] MRT-DoneCallback Task RSCalloutPrompt-10609-87 for RSCalloutPrompt-10609 [success]
[2009-03-12 08:44:26.524 'RSCalloutPrompt-10609' 2820 info] [RSCalloutPrompt-10609] SetTaskComplete
[2009-03-12 08:44:26.524 'RSCalloutPrompt-10609' 2820 info] SetRuntimeStatus for RSCalloutPrompt-10609 from running to success
[2009-03-12 08:44:26.539 'RSGroup-10610SecondaryShadowVMCleanup-Task' 2820 verbose] Task created
[2009-03-12 08:44:26.539 'RootStepList-10541-Task' 2820 info] Starting Task RSGroup-10610SecondaryShadowVMCleanup-88 for step RSGroup-10610
[2009-03-12 08:44:26.539 'RootStepList-10541-Task' 2820 verbose] MultipleRecoveryTask Info max 1 cur 1 remain 2
[2009-03-12 08:44:26.539 'RSCalloutPrompt-10609-Task' 2820 verbose] Task destroyed
[2009-03-12 08:44:26.539 'RSGroup-10610SecondaryShadowVMCleanup-Task' 2820 info] State set to running
[2009-03-12 08:44:26.539 'RSGroup-10610SecondaryShadowVMCleanup-Task' 2820 verbose] Scheduling work item
[2009-03-12 08:44:26.539 'RootStepList-10541-Task' 2820 info] MRT-Progress Task RSGroup-10610SecondaryShadowVMCleanup-88 for dr.secondary.RecoveryStep:RSGroup-10610 0
[2009-03-12 08:44:26.539 'RootStepList-10541-Task' 2820 verbose] Progress advanced to 63
[2009-03-12 08:44:26.539 'RSGroup-10610SecondaryShadowVMCleanup-Task' 2812 info] Running work method
[2009-03-12 08:44:26.539 'RSGroup-10610' 2812 info] SetRuntimeStatus for RSGroup-10610 from queued to running
[2009-03-12 08:44:26.555 'RSGroup-10610' 2812 info] Entering RecoveryStepGroup::StepPerform
[2009-03-12 08:44:26.555 'RSVm-10611-Task' 2812 verbose] Task created
[2009-03-12 08:44:26.570 'RecoveryContext-70-Task' 2804 verbose] GetState returned running
[2009-03-12 08:44:26.570 'RecoveryContext-70-Task' 2636 verbose] Progress advanced to 63
[2009-03-12 08:44:26.570 'RSGroup-10610SecondaryShadowVMCleanup-Task' 2812 info] Starting Task RSVm-10611-89 for step RSVm-10611
[2009-03-12 08:44:26.570 'RSGroup-10610SecondaryShadowVMCleanup-Task' 2812 verbose] MultipleRecoveryTask Info max 500 cur 1 remain 1
[2009-03-12 08:44:26.570 'RSGroup-10610SecondaryShadowVMCleanup-Task' 2804 info] MRT-Progress Task RSVm-10611-89 for dr.secondary.RecoveryStep:RSVm-10611 0
[2009-03-12 08:44:26.570 'RSGroup-10610SecondaryShadowVMCleanup-Task' 2804 verbose] Progress is unchanged
[2009-03-12 08:44:26.570 'RSVm-10611-Task' 2812 info] State set to running
[2009-03-12 08:44:26.570 'RSVm-10611-Task' 2812 verbose] Scheduling work item
[2009-03-12 08:44:26.570 'RSVm-10611-Task' 2804 info] Running work method
[2009-03-12 08:44:26.570 'RSVm-10611' 2804 info] SetRuntimeStatus for RSVm-10611 from queued to running
[2009-03-12 08:44:26.570 'RSVmPowerOff-10612-Task' 2804 verbose] Task created
[2009-03-12 08:44:26.585 'RSVm-10611-Task' 2804 info] Starting Task RSVmPowerOff-10612-90 for step RSVmPowerOff-10612
[2009-03-12 08:44:26.585 'RSVm-10611-Task' 2804 verbose] MultipleRecoveryTask Info max 1 cur 1 remain 0
[2009-03-12 08:44:26.585 'RSVmPowerOff-10612-Task' 2804 info] State set to running
[2009-03-12 08:44:26.585 'RSVmPowerOff-10612-Task' 2804 verbose] Scheduling work item
[2009-03-12 08:44:26.585 'RSVm-10611-Task' 2804 info] Not Starting Tasks MaxNumRunningTasks
[2009-03-12 08:44:26.585 'RSVm-10611-Task' 2804 info] Work function yielded
[2009-03-12 08:44:26.585 'RSVm-10611-Task' 2804 info] MRT-Progress Task RSVmPowerOff-10612-90 for dr.secondary.RecoveryStep:RSVmPowerOff-10612 0
[2009-03-12 08:44:26.585 'RSVm-10611-Task' 2804 verbose] Progress is unchanged
[2009-03-12 08:44:26.585 'RSVmPowerOff-10612-Task' 2804 info] Running work method
[2009-03-12 08:44:26.585 'RSVmPowerOff-10612' 2804 info] SetRuntimeStatus for RSVmPowerOff-10612 from queued to running
[2009-03-12 08:44:26.585 'RSVmPowerOff-10612' 2804 verbose] VM (vm-990) is already Powered Off
[2009-03-12 08:44:26.585 'RSVmPowerOff-10612-Task' 2804 verbose] Progress advanced to 100
[2009-03-12 08:44:26.585 'RSVmPowerOff-10612-Task' 2804 info] State set to success
[2009-03-12 08:44:26.585 'RSVmPowerOff-10612-Task' 2804 info] Work function completed successfully
[2009-03-12 08:44:26.585 'RSVm-10611-Task' 2804 info] MRT-Progress Task RSVmPowerOff-10612-90 for dr.secondary.RecoveryStep:RSVmPowerOff-10612 100
[2009-03-12 08:44:26.585 'RSVm-10611-Task' 2804 verbose] Progress advanced to 100
[2009-03-12 08:44:26.585 'RSVm-10611-Task' 2804 info] MRT-DoneCallback Task RSVmPowerOff-10612-90 for RSVmPowerOff-10612 [success]
[2009-03-12 08:44:26.585 'RSVmPowerOff-10612' 2804 info] [RSVmPowerOff-10612] SetTaskComplete
[2009-03-12 08:44:26.585 'RSVmPowerOff-10612' 2804 info] SetRuntimeStatus for RSVmPowerOff-10612 from running to success
[2009-03-12 08:44:26.585 'RSGroup-10610SecondaryShadowVMCleanup-Task' 2820 info] MRT-Progress Task RSVm-10611-89 for dr.secondary.RecoveryStep:RSVm-10611 100
[2009-03-12 08:44:26.585 'RSVm-10611-Task' 2804 verbose] Progress is unchanged
[2009-03-12 08:44:26.601 'RSVm-10611-Task' 2804 info] State set to success
[2009-03-12 08:44:26.601 'RSVm-10611-Task' 2804 info] Not Starting Tasks All Tasks Complete
[2009-03-12 08:44:26.601 'RSVmPowerOff-10612-Task' 2804 verbose] Task destroyed
[2009-03-12 08:44:26.601 'RSVm-10613-Task' 2812 verbose] Task created
[2009-03-12 08:44:26.601 'RSGroup-10610SecondaryShadowVMCleanup-Task' 2812 info] Starting Task RSVm-10613-91 for step RSVm-10613
[2009-03-12 08:44:26.601 'RSGroup-10610SecondaryShadowVMCleanup-Task' 2812 verbose] MultipleRecoveryTask Info max 500 cur 2 remain 0
[2009-03-12 08:44:26.601 'RSGroup-10610SecondaryShadowVMCleanup-Task' 2820 verbose] Progress advanced to 100
[2009-03-12 08:44:26.601 'RSGroup-10610SecondaryShadowVMCleanup-Task' 2820 info] MRT-DoneCallback Task RSVm-10611-89 for RSVm-10611 [success]
[2009-03-12 08:44:26.601 'RSVm-10611' 2820 info] [RSVm-10611] SetTaskComplete
[2009-03-12 08:44:26.601 'RSVm-10611' 2820 info] SetRuntimeStatus for RSVm-10611 from running to success
[2009-03-12 08:44:26.601 'RootStepList-10541-Task' 2804 info] MRT-Progress Task RSGroup-10610SecondaryShadowVMCleanup-88 for dr.secondary.RecoveryStep:RSGroup-10610 100
[2009-03-12 08:44:26.601 'RootStepList-10541-Task' 2804 verbose] Progress advanced to 72
[2009-03-12 08:44:26.601 'RecoveryContext-70-Task' 2840 verbose] Progress advanced to 72
[2009-03-12 08:44:26.601 'RSVm-10613-Task' 2812 info] State set to running
[2009-03-12 08:44:26.601 'RSVm-10613-Task' 2812 verbose] Scheduling work item
[2009-03-12 08:44:26.601 'RSVm-10613-Task' 2804 info] Running work method
[2009-03-12 08:44:26.601 'RSVm-10613' 2804 info] SetRuntimeStatus for RSVm-10613 from queued to running
[2009-03-12 08:44:26.616 'RSGroup-10610SecondaryShadowVMCleanup-Task' 2820 info] Not Starting Tasks All Tasks Running
[2009-03-12 08:44:26.616 'RSVm-10611-Task' 2820 verbose] Task destroyed
[2009-03-12 08:44:26.616 'RSGroup-10610SecondaryShadowVMCleanup-Task' 2820 info] MRT-Progress Task RSVm-10613-91 for dr.secondary.RecoveryStep:RSVm-10613 0
[2009-03-12 08:44:26.616 'RSGroup-10610SecondaryShadowVMCleanup-Task' 2812 info] Not Starting Tasks All Tasks Running
[2009-03-12 08:44:26.616 'RSGroup-10610SecondaryShadowVMCleanup-Task' 2812 info] Work function yielded
[2009-03-12 08:44:26.616 'RSVmPowerOff-10614-Task' 2804 verbose] Task created
[2009-03-12 08:44:26.616 'RSGroup-10610SecondaryShadowVMCleanup-Task' 2820 warning] Progress decreased from 100 to 50
[2009-03-12 08:44:26.616 'RootStepList-10541-Task' 2820 info] MRT-Progress Task RSGroup-10610SecondaryShadowVMCleanup-88 for dr.secondary.RecoveryStep:RSGroup-10610 50
[2009-03-12 08:44:26.616 'RootStepList-10541-Task' 2820 warning] Progress decreased from 72 to 67
[2009-03-12 08:44:26.616 'RecoveryContext-70-Task' 2636 warning] Progress decreased from 72 to 67
[2009-03-12 08:44:26.631 'RSVm-10613-Task' 2804 info] Starting Task RSVmPowerOff-10614-92 for step RSVmPowerOff-10614
[2009-03-12 08:44:26.631 'RSVm-10613-Task' 2804 verbose] MultipleRecoveryTask Info max 1 cur 1 remain 0
[2009-03-12 08:44:26.631 'RSVmPowerOff-10614-Task' 2804 info] State set to running
[2009-03-12 08:44:26.631 'RSVmPowerOff-10614-Task' 2804 verbose] Scheduling work item
[2009-03-12 08:44:26.631 'RSVm-10613-Task' 2804 info] Not Starting Tasks MaxNumRunningTasks
[2009-03-12 08:44:26.631 'RSVm-10613-Task' 2804 info] Work function yielded
[2009-03-12 08:44:26.631 'RSVm-10613-Task' 2804 info] MRT-Progress Task RSVmPowerOff-10614-92 for dr.secondary.RecoveryStep:RSVmPowerOff-10614 0
[2009-03-12 08:44:26.631 'RSVm-10613-Task' 2804 verbose] Progress is unchanged
[2009-03-12 08:44:26.631 'RSVmPowerOff-10614-Task' 2804 info] Running work method
[2009-03-12 08:44:26.631 'RSVmPowerOff-10614' 2804 info] SetRuntimeStatus for RSVmPowerOff-10614 from queued to running
[2009-03-12 08:44:26.631 'RSVmPowerOff-10614' 2804 verbose] VM (vm-992) is already Powered Off
[2009-03-12 08:44:26.631 'RSVmPowerOff-10614-Task' 2804 verbose] Progress advanced to 100
[2009-03-12 08:44:26.631 'RSVmPowerOff-10614-Task' 2804 info] State set to success
[2009-03-12 08:44:26.631 'RSVmPowerOff-10614-Task' 2804 info] Work function completed successfully
[2009-03-12 08:44:26.631 'RSVm-10613-Task' 2804 info] MRT-Progress Task RSVmPowerOff-10614-92 for dr.secondary.RecoveryStep:RSVmPowerOff-10614 100
[2009-03-12 08:44:26.631 'RSVm-10613-Task' 2804 verbose] Progress advanced to 100
[2009-03-12 08:44:26.631 'RSGroup-10610SecondaryShadowVMCleanup-Task' 2788 info] MRT-Progress Task RSVm-10613-91 for dr.secondary.RecoveryStep:RSVm-10613 100
[2009-03-12 08:44:26.631 'RSGroup-10610SecondaryShadowVMCleanup-Task' 2788 verbose] Progress advanced to 100
[2009-03-12 08:44:26.631 'RootStepList-10541-Task' 2788 info] MRT-Progress Task RSGroup-10610SecondaryShadowVMCleanup-88 for dr.secondary.RecoveryStep:RSGroup-10610 100
[2009-03-12 08:44:26.631 'RootStepList-10541-Task' 2788 verbose] Progress advanced to 72
[2009-03-12 08:44:26.631 'RecoveryContext-70-Task' 2840 verbose] Progress advanced to 72
[2009-03-12 08:44:26.631 'RSVm-10613-Task' 2804 info] MRT-DoneCallback Task RSVmPowerOff-10614-92 for RSVmPowerOff-10614 [success]
[2009-03-12 08:44:26.631 'RSVmPowerOff-10614' 2804 info] [RSVmPowerOff-10614] SetTaskComplete
[2009-03-12 08:44:26.631 'RSVmPowerOff-10614' 2804 info] SetRuntimeStatus for RSVmPowerOff-10614 from running to success
[2009-03-12 08:44:26.647 'RSVm-10613-Task' 2804 verbose] Progress is unchanged
[2009-03-12 08:44:26.647 'RSVm-10613-Task' 2804 info] State set to success
[2009-03-12 08:44:26.647 'RSVm-10613-Task' 2804 info] Not Starting Tasks All Tasks Complete
[2009-03-12 08:44:26.647 'RSVmPowerOff-10614-Task' 2804 verbose] Task destroyed
[2009-03-12 08:44:26.647 'RSGroup-10610SecondaryShadowVMCleanup-Task' 2804 info] MRT-DoneCallback Task RSVm-10613-91 for RSVm-10613 [success]
[2009-03-12 08:44:26.647 'RSVm-10613' 2804 info] [RSVm-10613] SetTaskComplete
[2009-03-12 08:44:26.647 'RSVm-10613' 2804 info] SetRuntimeStatus for RSVm-10613 from running to success
[2009-03-12 08:44:26.647 'RSGroup-10610SecondaryShadowVMCleanup-Task' 2804 verbose] Progress is unchanged
[2009-03-12 08:44:26.647 'RSGroup-10610SecondaryShadowVMCleanup-Task' 2804 info] State set to success
[2009-03-12 08:44:26.647 'RSGroup-10610SecondaryShadowVMCleanup-Task' 2804 info] Not Starting Tasks All Tasks Complete
[2009-03-12 08:44:26.647 'RSVm-10613-Task' 2804 verbose] Task destroyed
[2009-03-12 08:44:26.647 'RootStepList-10541-Task' 2804 info] MRT-DoneCallback Task RSGroup-10610SecondaryShadowVMCleanup-88 for RSGroup-10610 [success]
[2009-03-12 08:44:26.647 'RSGroup-10610' 2804 info] [RSGroup-10610] SetTaskComplete
[2009-03-12 08:44:26.647 'RSGroup-10610' 2804 info] SetRuntimeStatus for RSGroup-10610 from running to success
[2009-03-12 08:44:26.647 'RSGroup-10615SecondaryRunningVMResume-Task' 2804 verbose] Task created
[2009-03-12 08:44:26.662 'RootStepList-10541-Task' 2804 info] Starting Task RSGroup-10615SecondaryRunningVMResume-93 for step RSGroup-10615
[2009-03-12 08:44:26.662 'RootStepList-10541-Task' 2804 verbose] MultipleRecoveryTask Info max 1 cur 1 remain 1
[2009-03-12 08:44:26.662 'RSGroup-10610SecondaryShadowVMCleanup-Task' 2804 verbose] Task destroyed
[2009-03-12 08:44:26.662 'RSGroup-10615SecondaryRunningVMResume-Task' 2804 info] State set to running
[2009-03-12 08:44:26.662 'RSGroup-10615SecondaryRunningVMResume-Task' 2804 verbose] Scheduling work item
[2009-03-12 08:44:26.662 'RootStepList-10541-Task' 2804 info] MRT-Progress Task RSGroup-10615SecondaryRunningVMResume-93 for dr.secondary.RecoveryStep:RSGroup-10615 0
[2009-03-12 08:44:26.662 'RootStepList-10541-Task' 2804 verbose] Progress is unchanged
[2009-03-12 08:44:26.662 'RSGroup-10615SecondaryRunningVMResume-Task' 2804 info] Running work method
[2009-03-12 08:44:26.662 'RSGroup-10615' 2804 info] SetRuntimeStatus for RSGroup-10615 from queued to running
[2009-03-12 08:44:26.662 'RSGroup-10615' 2804 info] Entering RecoveryStepGroup::StepPerform
[2009-03-12 08:44:26.662 'RSGroup-10615SecondaryRunningVMResume-Task' 2804 info] MultipleRecoveryTask Nothing to do - exiting.
[2009-03-12 08:44:26.662 'RSGroup-10615SecondaryRunningVMResume-Task' 2804 info] Work function completed successfully
[2009-03-12 08:44:26.662 'RSGroup-10615SecondaryRunningVMResume-Task' 2804 info] State set to success
[2009-03-12 08:44:26.662 'RootStepList-10541-Task' 2804 info] MRT-DoneCallback Task RSGroup-10615SecondaryRunningVMResume-93 for RSGroup-10615 [success]
[2009-03-12 08:44:26.662 'RSGroup-10615' 2804 info] [RSGroup-10615] SetTaskComplete
[2009-03-12 08:44:26.662 'RSGroup-10615' 2804 info] SetRuntimeStatus for RSGroup-10615 from running to success
[2009-03-12 08:44:26.678 'RSStorageOperationList-10616-Task' 2804 verbose] Task created
[2009-03-12 08:44:26.678 'RootStepList-10541-Task' 2804 info] Starting Task RSStorageOperationList-10616-94 for step RSStorageOperationList-10616
[2009-03-12 08:44:26.678 'RootStepList-10541-Task' 2804 verbose] MultipleRecoveryTask Info max 1 cur 1 remain 0
[2009-03-12 08:44:26.678 'RSGroup-10615SecondaryRunningVMResume-Task' 2804 verbose] Task destroyed
[2009-03-12 08:44:26.678 'RSStorageOperationList-10616-Task' 2804 info] State set to running
[2009-03-12 08:44:26.678 'RSStorageOperationList-10616-Task' 2804 verbose] Scheduling work item
[2009-03-12 08:44:26.678 'RootStepList-10541-Task' 2804 info] MRT-Progress Task RSStorageOperationList-10616-94 for dr.secondary.RecoveryStep:RSStorageOperationList-10616 0
[2009-03-12 08:44:26.678 'RootStepList-10541-Task' 2804 verbose] Progress advanced to 81
[2009-03-12 08:44:26.678 'RSStorageOperationList-10616-Task' 2776 info] Running work method
[2009-03-12 08:44:26.678 'RSStorageOperationList-10616' 2776 info] SetRuntimeStatus for RSStorageOperationList-10616 from queued to running
[2009-03-12 08:44:26.678 'RecoveryContext-70-Task' 2788 verbose] Progress advanced to 81
[2009-03-12 08:44:26.693 'RSStorageOperationList-10616' 2776 info] [RSStorageOperationList-10616] Entering RecoveryStepStorageOperationList::StepPerform
[2009-03-12 08:44:26.693 'EndImageTest-Task' 2776 verbose] Task created
[2009-03-12 08:44:26.693 'SimpleTaskManager' 2776 verbose] Adding task EndImageTest-95
[2009-03-12 08:44:26.693 'EndImageTest-Task' 2776 info] State set to running
[2009-03-12 08:44:26.693 'EndImageTest-Task' 2776 verbose] Scheduling work item
[2009-03-12 08:44:26.693 'SecondaryReplication' 2776 verbose] Changing recovery state of 'shadow-group-4245' to 'finishingTest'
[2009-03-12 08:44:26.693 'SecondaryReplication' 2776 verbose] Saving ShadowGroup to DB object
[2009-03-12 08:44:26.693 'EndImageTest-Task' 2804 info] Running work method
[2009-03-12 08:44:26.693 'EndImageTest-Task' 2804 info] Work function yielded
[2009-03-12 08:44:26.693 'RSStorageOperation-10617-Task' 2776 verbose] Task created
[2009-03-12 08:44:26.693 'SecondarySanProvider' 2788 warning] Shadow virtual machine 'shadow-vm-10300' is not being tested
[2009-03-12 08:44:26.693 'SecondarySanProvider' 2788 trivia] 'Reset VM 'shadow-vm-10300' after test' took 0 seconds
[2009-03-12 08:44:26.693 'SecondarySanProvider' 2788 warning] Shadow virtual machine 'shadow-vm-10379' is not being tested
[2009-03-12 08:44:26.693 'SecondarySanProvider' 2788 trivia] 'Reset VM 'shadow-vm-10379' after test' took 0 seconds
[2009-03-12 08:44:26.724 'RSStorageOperationList-10616-Task' 2776 info] Starting Task RSStorageOperation-10617-96 for step RSStorageOperation-10617
[2009-03-12 08:44:26.724 'RSStorageOperationList-10616-Task' 2776 verbose] MultipleRecoveryTask Info max 1 cur 1 remain 0
[2009-03-12 08:44:26.724 'RSStorageOperation-10617-Task' 2776 info] State set to running
[2009-03-12 08:44:26.724 'RSStorageOperation-10617-Task' 2776 verbose] Scheduling work item
[2009-03-12 08:44:26.724 'RSStorageOperationList-10616-Task' 2776 info] Not Starting Tasks MaxNumRunningTasks
[2009-03-12 08:44:26.724 'RSStorageOperationList-10616-Task' 2776 info] Work function yielded
[2009-03-12 08:44:26.724 'RSStorageOperationList-10616-Task' 2776 info] MRT-Progress Task RSStorageOperation-10617-96 for dr.secondary.RecoveryStep:RSStorageOperation-10617 0
[2009-03-12 08:44:26.724 'RSStorageOperationList-10616-Task' 2776 verbose] Progress is unchanged
[2009-03-12 08:44:26.724 'RSStorageOperation-10617-Task' 2776 info] Running work method
[2009-03-12 08:44:26.724 'RSStorageOperation-10617' 2776 info] SetRuntimeStatus for RSStorageOperation-10617 from queued to running
[2009-03-12 08:44:26.724 'RSStorageOperation-10617-Task' 2776 verbose] YieldableRecoveryTask::CreateMultiLocalTaskWrapper
[2009-03-12 08:44:26.724 'RSStorageOperation-10617-Task' 2776 verbose] YieldableRecoveryTask::AddTaskToMultiTaskWrapper
[2009-03-12 08:44:26.724 'RSStorageOperation-10617-Task' 2776 info] Work function yielded
[2009-03-12 08:44:26.724 'RSStorageOperation-10617-Task' 2776 verbose] Progress is unchanged
[2009-03-12 08:44:26.785 'SecondarySanProvider' 2788 trivia] 'Reset 2 VMs in group 'shadow-group-4245' after test' took 0.092 seconds
[2009-03-12 08:44:26.785 'SecondarySanProvider' 2788 verbose] Deleting lun snapshots for group 'SRM_FP_OS'
[2009-03-12 08:44:26.785 'SecondarySanProvider' 2788 info] Command Line for testFailover: "E:\Program Files\VMware\VMware Site Recovery Manager\external\perl-5.8.8\bin\perl.exe" "E:/Program Files/VMware/VMware Site Recovery Manager/scripts/SAN/LeftHand Networks/command.pl"
[2009-03-12 08:44:26.785 'SecondarySanProvider' 2788 verbose] Input for testFailover: <?xml version="1.0" encoding="UTF-8"?>
[#2] <Command>
[#2]   <Name>testFailover</Name>
[#2]   <ConnectSpec>
[#2]     <Name>SAN/iQ</Name>
[#2]     <Address>10.19.49.64</Address>
[#2]     <Address>10.19.49.62</Address>
[#2]     <Username>gotts</Username>
[#2]     <Password>********</Password>
[#2]   </ConnectSpec>
[#2]   <Action>stop</Action>
[#2]   <ArrayId>SRM_FP;2866F8D055E8E47D48C3F8BBC5C2BAE3</ArrayId>
[#2]   <ReplicaLunKeyList>
[#2]     <ReplicaLunKey>007C420D5785E225AE6F82584BC73585;SRM_LV;30;SRM_LV_Sch_RS_1_Pri</ReplicaLunKey>
[#2]   </ReplicaLunKeyList>
[#2]   <OutputFile>C:\WINDOWS\TEMP\vmware-SYSTEM\dr-sanprovider0</OutputFile>
[#2]   <LogLevel>trivia</LogLevel>
[#2] </Command>
[2009-03-12 08:44:26.785 'SecondarySanProvider' 2788 trivia] Environment ALLUSERSPROFILE=C:\Documents and Settings\All Users will be set for the script
[2009-03-12 08:44:26.785 'SecondarySanProvider' 2788 trivia] Environment ClusterLog=C:\WINDOWS\Cluster\cluster.log will be set for the script
[2009-03-12 08:44:26.800 'SecondarySanProvider' 2788 trivia] Environment CommonProgramFiles=C:\Program Files\Common Files will be set for the script
[2009-03-12 08:44:26.800 'SecondarySanProvider' 2788 trivia] Environment COMPUTERNAME=RSFP2K3VC25 will be set for the script
[2009-03-12 08:44:26.800 'SecondarySanProvider' 2788 trivia] Environment ComSpec=C:\WINDOWS\system32\cmd.exe will be set for the script
[2009-03-12 08:44:26.800 'SecondarySanProvider' 2788 trivia] Environment DEFLOGDIR=C:\Documents and Settings\All Users\Application Data\McAfee\DesktopProtection will be set for the script
[2009-03-12 08:44:26.800 'SecondarySanProvider' 2788 trivia] Environment FP_NO_HOST_CHECK=NO will be set for the script
[2009-03-12 08:44:26.800 'SecondarySanProvider' 2788 trivia] Environment NUMBER_OF_PROCESSORS=1 will be set for the script
[2009-03-12 08:44:26.800 'SecondarySanProvider' 2788 trivia] Environment OS=Windows_NT will be set for the script
[2009-03-12 08:44:26.800 'SecondarySanProvider' 2788 trivia] Environment Path=C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\Program Files\Microsoft SQL Server\90\Tools\binn\ will be set for the script
[2009-03-12 08:44:26.800 'SecondarySanProvider' 2788 trivia] Environment PATHEXT=.COM;.EXE;.BAT;.CMD;.VBS;.VBE;.JS;.JSE;.WSF;.WSH will be set for the script
[2009-03-12 08:44:26.800 'SecondarySanProvider' 2788 trivia] Environment PROCESSOR_ARCHITECTURE=x86 will be set for the script
[2009-03-12 08:44:26.800 'SecondarySanProvider' 2788 trivia] Environment PROCESSOR_IDENTIFIER=x86 Family 16 Model 2 Stepping 3, AuthenticAMD will be set for the script
[2009-03-12 08:44:26.800 'SecondarySanProvider' 2788 trivia] Environment PROCESSOR_LEVEL=16 will be set for the script
[2009-03-12 08:44:26.800 'SecondarySanProvider' 2788 trivia] Environment PROCESSOR_REVISION=0203 will be set for the script
[2009-03-12 08:44:26.800 'SecondarySanProvider' 2788 trivia] Environment ProgramFiles=C:\Program Files will be set for the script
[2009-03-12 08:44:26.800 'SecondarySanProvider' 2788 trivia] Environment SystemDrive=C: will be set for the script
[2009-03-12 08:44:26.800 'SecondarySanProvider' 2788 trivia] Environment SystemRoot=C:\WINDOWS will be set for the script
[2009-03-12 08:44:26.800 'SecondarySanProvider' 2788 trivia] Environment TEMP=C:\WINDOWS\TEMP will be set for the script
[2009-03-12 08:44:26.800 'SecondarySanProvider' 2788 trivia] Environment TMP=C:\WINDOWS\TEMP will be set for the script
[2009-03-12 08:44:26.800 'SecondarySanProvider' 2788 trivia] Environment USERPROFILE=C:\Documents and Settings\Default User will be set for the script
[2009-03-12 08:44:26.800 'SecondarySanProvider' 2788 trivia] Environment VSEDEFLOGDIR=C:\Documents and Settings\All Users\Application Data\McAfee\DesktopProtection will be set for the script
[2009-03-12 08:44:26.800 'SecondarySanProvider' 2788 trivia] Environment windir=C:\WINDOWS will be set for the script
[2009-03-12 08:44:26.800 'SysCommandLineWin32' 2788 verbose] Starting process: "E:\\Program Files\\VMware\\VMware Site Recovery Manager\\external\\perl-5.8.8\\bin\\perl.exe" "E:/Program Files/VMware/VMware Site Recovery Manager/scripts/SAN/LeftHand Networks/command.pl"
[2009-03-12 08:44:27.092 'SecondarySanProvider' 2788 info] testFailover exited with exit code 0
[2009-03-12 08:44:27.092 'SecondarySanProvider' 2788 trivia] testFailover's output:
"E:\Program Files\VMware\VMware Site Recovery Manager\/scripts/SAN/LeftHand Networks/jre/bin/java" -cp "E:\Program Files\VMware\VMware Site Recovery Manager\/scripts/SAN/LeftHand Networks/UI.jar" com.lefthandnetworks.commandline.Srm.Srm < "E:\Program Files\VMware\VMware Site Recovery Manager\/scripts/SAN/LeftHand Networks/XMLinput.xml""
[#2] #
[#2] # An unexpected error has been detected by Java Runtime Environment:
[#2] #
[#2] #  EXCEPTION_ACCESS_VIOLATION (0xc0000005) at pc=0x6d894136, pid=3912, tid=3936
[#2] #
[#2] # Java VM: Java HotSpot(TM) Client VM (1.6.0_01-b06 mixed mode)
[#2] # Problematic frame:
[#2] #
[#2] # An error report file with more information is saved as hs_err_pid3912.log
[#2] #
[#2] # If you would like to submit a bug report, please visit:
[#2] #
[2009-03-12 08:44:27.092 'SecondarySanProvider' 2788 trivia] 'testFailover' returned
[2009-03-12 08:44:27.092 'SecondarySanProvider' 2788 error] Failed to retrieve script results
[2009-03-12 08:44:27.092 'SecondarySanProvider' 2788 warning] Failed to delete lun snapshots: Unexpected exception 'class Vmacore::Xml::XMLParseException' XML document is empty
[2009-03-12 08:44:27.523 'SecondarySanProvider' 2788 trivia] 'Retrieved 2 properties of 2 objects of type 'vim.HostSystem'' took 0.43 seconds
[2009-03-12 08:44:27.523 'SecondarySanProvider' 2788 trivia] Skipping HBA which is neither FC nor iSCSI:
(vim.host.ParallelScsiHba) {
[#2]    dynamicType = <unset>,
[#2]    key = "key-vim.host.ParallelScsiHba-vmhba0",
[#2]    device = "vmhba0",
[#2]    bus = 12,
[#2]    status = "unknown",
[#2]    model = "ServeRAID 8k/8k-l8 (Aurora)",
[#2]    driver = "aacraid_esx30",
[#2]    pci = "0c:00.0",
[#2] }
[2009-03-12 08:44:27.523 'SecondarySanProvider' 2788 trivia] Looking for 1 static iSCSI targets to remove from host 'host-594'
[2009-03-12 08:44:27.538 'SecondarySanProvider' 2788 trivia] Skipping HBA which is neither FC nor iSCSI:
(vim.host.ParallelScsiHba) {
[#2]    dynamicType = <unset>,
[#2]    key = "key-vim.host.ParallelScsiHba-vmhba0",
[#2]    device = "vmhba0",
[#2]    bus = 12,
[#2]    status = "unknown",
[#2]    model = "ServeRAID 8k/8k-l8 (Aurora)",
[#2]    driver = "aacraid_esx30",
[#2]    pci = "0c:00.0",
[#2] }
[2009-03-12 08:44:27.538 'SecondarySanProvider' 2788 trivia] Looking for 1 static iSCSI targets to remove from host 'host-559'
[2009-03-12 08:44:27.538 'SecondarySanProvider' 2788 trivia] 'Reset storage for group 'shadow-group-4245' after test' took 0.752 seconds
[2009-03-12 08:44:27.538 'EndImageTest-Task' 2788 verbose] Progress advanced to 50
[2009-03-12 08:44:27.538 'SecondarySanProvider' 2788 verbose] Rescanning host 'host-559'
[2009-03-12 08:44:27.538 'DatastoreLocator.RescanHost-Task' 2788 verbose] Task created
[2009-03-12 08:44:27.538 'SimpleTaskManager' 2788 verbose] Adding task DatastoreLocator.RescanHost-97
[2009-03-12 08:44:27.538 'DatastoreLocator.RescanHost-Task' 2788 info] State set to running
[2009-03-12 08:44:27.538 'DatastoreLocator.RescanHost-Task' 2788 verbose] Scheduling work item
[2009-03-12 08:44:27.538 'RSStorageOperation-10617-Task' 2820 verbose] Progress advanced to 50
[2009-03-12 08:44:27.538 'DatastoreLocator.RescanHost-Task' 2776 info] Running work method
[2009-03-12 08:44:27.538 'RSStorageOperationList-10616-Task' 2836 info] MRT-Progress Task RSStorageOperation-10617-96 for dr.secondary.RecoveryStep:RSStorageOperation-10617 50
[2009-03-12 08:44:27.538 'RSStorageOperationList-10616-Task' 2836 verbose] Progress advanced to 50
[2009-03-12 08:44:27.538 'RootStepList-10541-Task' 2636 info] MRT-Progress Task RSStorageOperationList-10616-94 for dr.secondary.RecoveryStep:RSStorageOperationList-10616 50
[2009-03-12 08:44:27.538 'RootStepList-10541-Task' 2636 verbose] Progress advanced to 86
[2009-03-12 08:44:27.538 'RecoveryContext-70-Task' 2820 verbose] Progress advanced to 86
[2009-03-12 08:44:27.569 'SecondarySanProvider' 2788 verbose] Rescanning host 'host-594'
[2009-03-12 08:44:27.569 'DatastoreLocator.RescanHost-Task' 2788 verbose] Task created
[2009-03-12 08:44:27.569 'SimpleTaskManager' 2788 verbose] Adding task DatastoreLocator.RescanHost-98
[2009-03-12 08:44:27.569 'DatastoreLocator.RescanHost-Task' 2788 info] State set to running
[2009-03-12 08:44:27.569 'DatastoreLocator.RescanHost-Task' 2788 verbose] Scheduling work item
[2009-03-12 08:44:27.569 'DatastoreLocator.RescanHost-Task' 2780 info] Running work method
[2009-03-12 08:44:27.584 'SecondarySanProvider' 2788 trivia] MLTW, handling task progress
[2009-03-12 08:44:27.584 'SecondarySanProvider' 2788 trivia] MLTW, handling task state
[2009-03-12 08:44:27.584 'SecondarySanProvider' 2788 trivia] MLTW, handling task progress
[2009-03-12 08:44:27.584 'SecondarySanProvider' 2788 trivia] MLTW, handling task state
0 Kudos
admin
Immortal
Immortal

Hi gotts,

As you pointed out the logs you posted failed much earlier than IP Customization. Looking at your logs it seems that the error occured when failing over the storage:

"E:\Program Files\VMware\VMware Site Recovery Manager\/scripts/SAN/LeftHand Networks/jre/bin/java" -cp "E:\Program Files\VMware\VMware Site Recovery Manager\/scripts/SAN/LeftHand Networks/UI.jar"

com.lefthandnetworks.commandline.Srm.Srm < "E:\Program Files\VMware\VMware Site Recovery Manager\/scripts/SAN/LeftHand Networks/XMLinput.xml""

2 #

2 # An unexpected error has been detected by Java Runtime Environment:

2 #

2 # EXCEPTION_ACCESS_VIOLATION (0xc0000005) at pc=0x6d894136, pid=132, tid=2716

2 #

2 # Java VM: Java HotSpot(TM) Client VM (1.6.0_01-b06 mixed mode)

2 # Problematic frame:

2 # V http://jvm.dll+0xd4136

2 #

2 # An error report file with more information is saved as hs_err_pid132.log

2 #

2 # If you would like to submit a bug report, please visit:

2 # http://java.sun.com/webapps/bugreport/crash.jsp

2 #

This error happened after SRM had failed over the storage for the test, when SRM was trying to get information about the new LUNs. I am not sure if the issue is with your JVM installation, or with the Array scripts. Can you reproduce this error consistently?

Would it be possible for you to post the logs from the previous runs were IP Customization failed?

Thanks,

Fabio Rojas

0 Kudos
gotts
Enthusiast
Enthusiast

I have an issue on one site that is related to the array scripts but the other site is working. I had bi-directional recovery set up but now I can only recover in one direction. I will try to run the SRM install on the site with the array script problem today. In the meantime I will also post the logs from the site that is still functional but fails when I try to do the IP Customization.

0 Kudos
gotts
Enthusiast
Enthusiast

Here is a log file that contains a successful recovery with out the IP Customization and a failed recovery with Customization.

0 Kudos
Smoggy
VMware Employee
VMware Employee

I think we spoke about this on email?

1. your SRA install for left hand seems shot on one of your SRM servers. the JRE crash errors do not look good. I would suggest you double check the JRE and possibly reinstall it and the SRA. ensure your using the SRA from vmware.com and not one obtained through any other source. there have been instances recently of people using pre-release or beta adapters obtained directly from their storage vendor.

2. during the recovery WITH ip-customization your timing out at the change network settings stage. I think I mentioned in an email that when you see this timeout starting then is the time to open a console to that virtual machine. when you log in to the windows console of the VM as the administrator you will see a dos window open and it will contain output from the running guest customization script. also in that window will be stated the location of the log file for that customization run. you need to review the log file to determine where your customization process is failing or timing out. you will only be able to work this out by loggin into the VM during the recovery and taking a look. If you do not do this and simply end the test and reset it then you've lost those logs. the guest customization log file within the recovered VM will usually be something like: C:\TEMP\+vmware-imc\guestcust.log+

this is just my 2cents but that is how i would start to troubleshoot the issue.

best regards,

Lee Dilworth

admin
Immortal
Immortal

Gotts,

I looked through your logs. Customization is failing because SRM cannot mount the VM's disks locally:

Found host host-549 for vm-1012

hostVersion = 3.0.2, tools version = 7202

opening disk RSFP2K3SRM2/RSFP2K3SRM2.vmdk

Using connection string = vpxa-nfc://[snap-00000002-RSFPVSAN_OS (2)] RSFP2K3SRM2/RSFP2K3SRM2.vmdk@rslvcitrixesx1:902!52 72 48 e5 2a d9 67 47-51 b6 14 e2 73 ca f6 09

Error occured while deploying package. Msg: Failed to open disk RSFP2K3SRM2/RSFP2K3SRM2.vmdk: Cannot open disk file: Error : Disk library failed (NBD_ERR_NETWORK_CONNECT). Unable to open 'vpxa-nfc://[snap-00000002-RSFPVSAN_OS (2)] RSFP2K3SRM2/RSFP2K3SRM2.vmdk@rslvcitrixesx1:902!52 72 48 e5 2a d9 67 47-51 b6 14 e2 73 ca f6 09'. Failed to configure disk scsi0:0. (0x80040204)

You are using ESX 3.0.2. When customizing VM's running on ESX 3.0.2 SRM uses a tool called Vmount to mount those disks on the SRM server. It then places a customizaton package inside of the VM's disks. The Vmount operation is failing. This can happen for a few reasons but it usually indicates that there is a problem on the host. Can you verify that you are up to date on all of the ESX patches. Also would it be possible for you to restart the hostd and vpxa process on the host? This should not affect the VM's. It would also be useful to look at the vm-support logs for the host rslvcitrixesx.

Thank you,

Fabio Rojas

gotts
Enthusiast
Enthusiast

I will re-run the SRA install on the site that has issues. I got the adapter from VMWARE. I have the log file information you suggested here:

Customization in progress set to 1 at 2009-Mar-04 09:23:14

Rpci: Sending request='deployPkg.update.state 4 0 C:\WINDOWS\TEMP\vmware-imc\guestcust.log'

Rpci: Sent request='deployPkg.update.state 4 0 C:\WINDOWS\TEMP\vmware-imc\guestcust.log', reply='Unknown command', len=15, status=0

Unable to set customization status in vmx.

Successfully opened key SYSTEM\CurrentControlSet\Control\Session Manager\

Size of reg_multi_sz 21.

Read multi_sz value from registry autocheck autochk *, size 21.

string value from registry autocheck autochk *.

Returning 1 elements

Got BootExecute from session mgr.

Native App sysprepDecrypter.exe, arguments ''

Copied file sysprepDecrypter.exe to C:\WINDOWS\system32\sysprepDecrypter.exe

Updated boot execute value.

Successfully created/opened key SOFTWARE\VMware, Inc.\Guest Customization\

New boot execute:

autocheck autochk *

sysprepDecrypter.exe

Rpci: Sending request='deployPkg.update.state 4 102 C:\WINDOWS\TEMP\vmware-imc\guestcust.log@Sysprep version 5.00.2195.2104 is not compatible with guest os version 5.2@5.00.2195.2104@5.2'

Rpci: Sent request='deployPkg.update.state 4 102 C:\WINDOWS\TEMP\vmware-imc\guestcust.log@Sysprep version 5.00.2195.2104 is not compatible with guest os version 5.2@5.00.2195.2104@5.2', reply='Unknown command', len=15, status=0

Unable to set customization status in vmx.

Looks like an issue with Sysprep but I am not aware of how to correct the issue.

0 Kudos
Smoggy
VMware Employee
VMware Employee

what OS version are the VM's your trying to recover???

your guest customization log suggests that the sysprep version being used is Windows 2000 Sysprep (Sysprep version 5.00.2195.2104).

if your VM's being recovered in the recovery plan are NOT Windows 2000 then guest customization is going to fail. If this is the case then it sounds like your VC server at the recovery site does not have access to the necessary sysprep files for all of the Windows versions you are using.

You obtain sysprep from microsoft, for most windows builds you can extract them from the deploy.cab file located in the deployment tools folder on the OS media CD/DVD. Once you have the necessary deploy.cab for the version of windows you wish to customize in virtualcenter you must extract the contents of the.cab file to the correct location on your virtualcenter server.

If you login to the recovery site virtualcenter server navigate to this folder: C:\Documents and Settings\All Users\Application Data\VMware\VMware VirtualCenter\sysprep under here you will see the subfolder "stubs" for the various windows builds. initially these subfolders will be empty until you download/locate the deploy.cab files that match the OS version for that sub folder and then extract the contents into this folder.

this webpage has some info and links for the major versions:

http://www.vm-help.com/esx/other/sysprep_download_links.html

I would suggest, based on the errors that you first check the version of windows your recovering that hangs on "change network settings" and then verify that on the recovery site VC server you have the necessary sysprep files located in the C:\Documents and Settings\All Users\Application Data\VMware\VMware VirtualCenter\sysprep\&lt;youOStype&gt; folder.

hope this helps,

Lee Dilworth

View solution in original post

0 Kudos