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