Test fails with error code -1

ckh201110141 · ‎12-16-2011

Here is my problem.

I am doing a test of 3 different servers in two seperate volumes. I am using array based replication. The guest VMs are Server 2003 Standard R2 x64 and Server 2003 Standard R2. One is an Exchange 2007 server holding the mailboxes. The other two are for OWA and a front end server.

I am running vCenter 5 at both the Protected and Recovery locations with SRM 5. All of the hosts are ESXi 5 as well.

The problem is that when I run a test on these they fail at the point of customizing the IP at the Recovery location for all of the servers. If I don't customize the IP they don't have any problems. What is really weird is that I have a few test 2008 R2 servers in another volume that customize the IPs without any problems. I know the compatibiliy matrix says that 2003 Datacenter (32 and 64 bit) is supported and I would assume that 2003 Standard (32 and 64 bit) would be supported as well. Am I correct in this? I've found the KBs from VMware and checked through those (although they didn't list SRM 5 as one of the versions that had the problem) and everything looks good. Also I am not running any custom scripts.

As I was looking through the log I noticed that it said that there were two adapters for one MAC. Could this be causing the problem?

Below is the error from SRM and what I could find in the logs. Any help would be great!

Thanks!

SRM History Error:

Error - Cannot complete customization, possibly due to a scripting runtime error or invalid script parameters (Error code: -1). IP settings may have been partially applied.

SRM Log:

011-12-15T13:12:33.721-05:00 [07032 info 'Recovery' ctxID=1a7741a7] [recovery-plan-30793.ipCust-protected-vm-30728-IPCustomization] Copying guest output from guest path C:\WINDOWS\TEMP\vmware0 to SRM server path C:\Windows\TEMP\vmware-SYSTEM21

2011-12-15T13:12:34.002-05:00 [07032 verbose 'VixVcDomain'] Decrementing host config refcount for VIX Login

2011-12-15T13:12:34.002-05:00 [07032 info 'VixVm-vm-379'] Unsetting VM config for shared secret

2011-12-15T13:12:34.002-05:00 [05924 verbose 'VixVcDomain'] Finishing Host Configuration for shared secret on Host

2011-12-15T13:12:34.002-05:00 [05924 info 'VixVcDomain'] Shared Policy RefCount for host [vim.HostSystem:host-261]: 1

2011-12-15T13:12:34.002-05:00 [05924 verbose 'VixVcDomain'] Updating shared secret refcount on host [vim.HostSystem:host-261] to: 0

2011-12-15T13:12:34.049-05:00 [05924 verbose 'LocalVC'] [PCM] Using token '1024' for pending filter creation

2011-12-15T13:12:39.080-05:00 [04132 verbose 'LocalVC'] [PCM] Destroying filter with filter token '1024'

2011-12-15T13:12:39.080-05:00 [04132 info 'VixVm-vm-379'] Guest Session Done.

2011-12-15T13:12:39.127-05:00 [06532 error 'Recovery' ctxID=1a7741a7] [recovery-plan-30793.ipCust-protected-vm-30728-IPCustomization] Guest command on VM: [vim.VirtualMachine:vm-379] failed with exit code: -1

2011-12-15T13:12:39.158-05:00 [06532 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ASSIGN: items[19], 5238f657-dd1d-0cf7-cd07-dd98e76d4b59

2011-12-15T13:12:39.158-05:00 [06532 warning 'Recovery' ctxID=1a7741a7] [recovery-plan-30793.ipCust-protected-vm-30728-IPCustomization] Guest Operation failed for VM [vim.VirtualMachine:vm-379]

2011-12-15T13:12:39.158-05:00 [06532 error 'Recovery' ctxID=1a7741a7] [recovery-plan-30793.ipCust-protected-vm-30728] IP Customization failed for VM ExchangeFEVM [vm-379]: (dr.recovery.fault.IPCustomizationFailure) {

--> dynamicType = <unset>,

--> faultCause = (vmodl.MethodFault) null,

--> result = (dr.recovery.CalloutResult) {

--> dynamicType = <unset>,

--> commandLine = "echo "Starting IP customization on Windows ..." >> "%VMware_GuestOp_OutputFile%"

--> cscript "%VMware_GuestOp_File_1%" /MacAddress:00:50:56:9d:04:37 /WINSserver:DELETEALL >> "%VMware_GuestOp_OutputFile%" 2>&1

--> echo Exit code: %ERRORLEVEL% >> "%VMware_GuestOp_OutputFile%"

--> if not %ERRORLEVEL% == 0 exit %ERRORLEVEL%

--> "%VMware_GuestOp_File_0%" setupNic -m 00:50:56:9d:04:37 -s 10.120.187.55 -su 255.255.255.0 >> "%VMware_GuestOp_OutputFile%" 2>&1

--> echo Exit code: %ERRORLEVEL% >> "%VMware_GuestOp_OutputFile%"

--> if not %ERRORLEVEL% == 0 exit %ERRORLEVEL%

--> "%VMware_GuestOp_File_0%" setupNic -m 00:50:56:9d:04:37 -g 10.120.187.1 -gm 1 -d 10.120.187.150 -t 0 >> "%VMware_GuestOp_OutputFile%" 2>&1

--> echo Exit code: %ERRORLEVEL% >> "%VMware_GuestOp_OutputFile%"

--> if not %ERRORLEVEL% == 0 exit %ERRORLEVEL%

--> ping -n 15 127.0.0.1 >nul >> "%VMware_GuestOp_OutputFile%" 2>&1

--> echo Exit code: %ERRORLEVEL% >> "%VMware_GuestOp_OutputFile%"

--> if not %ERRORLEVEL% == 0 exit %ERRORLEVEL%

--> cscript "%VMware_GuestOp_File_1%" /MacAddress:00:50:56:9d:04:37 /Reset:ALLNICS >> "%VMware_GuestOp_OutputFile%" 2>&1

--> echo Exit code: %ERRORLEVEL% >> "%VMware_GuestOp_OutputFile%"

--> if not %ERRORLEVEL% == 0 exit %ERRORLEVEL%

--> type "%TEMP%\vmware-imc\guestcust.log" >> "%VMware_GuestOp_OutputFile%"

--> ",

--> output = "Guest Script Output at: C:\Windows\TEMP\vmware-SYSTEM21

--> "Starting IP customization on Windows ..."

--> Microsoft (R) Windows Script Host Version 5.6

-->

--> MAC Address: 00:50:56:9d:04:37

--> Reset level:

--> Enum script:

--> IP Address:

--> Subnet prefix length:

--> Subnet Address:

--> Gateway:

--> Gateway Metric:

--> DNS server:

--> WINS server: DELETEALL

-->

--> Error: WMI returned 2 adapters for the given MAC address.

--> Exit code: -1

--> ",

--> returnValue = -1,

--> },

--> msg = "",

--> }

2011-12-15T13:12:39.158-05:00 [06532 trivia 'Recovery' ctxID=1a7741a7] Destroying child job, child: recovery-plan-30793.ipCust-protected-vm-30728-IPCustomization <recovery-plan-30793.11.5.4> [class Dr::Recovery::Engine::InGuestCommandJob] parent: recovery-plan-30793.ipCust-protected-vm-30728 <recovery-plan-30793.11.5> [class Dr::Recovery::Engine::PrepareVmMasterJob]

2011-12-15T13:12:39.158-05:00 [06532 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ASSIGN: items[20], 5238f657-dd1d-0cf7-cd07-dd98e76d4b59

2011-12-15T13:12:39.158-05:00 [06532 trivia 'Recovery' ctxID=1a7741a7] New job created, name: recovery-plan-30793.ipCust-protected-vm-30728-GuestPowerOff

2011-12-15T13:12:39.158-05:00 [06532 trivia 'Recovery' ctxID=1a7741a7] Adding child job, child: recovery-plan-30793.ipCust-protected-vm-30728-GuestPowerOff <non-persisted> [class Dr::Recovery::Engine::PowerOffVmJob] parent: recovery-plan-30793.ipCust-protected-vm-30728 <recovery-plan-30793.11.5> [class Dr::Recovery::Engine::PrepareVmMasterJob]

2011-12-15T13:12:39.158-05:00 [06532 warning 'Default' ctxID=1a7741a7] The progress of this work handle has been overcomitted. Total child ticks is now 8 out of a possible 7

2011-12-15T13:12:39.158-05:00 [06532 trivia 'Recovery' ctxID=1a7741a7] Commit and yield, job: recovery-plan-30793.ipCust-protected-vm-30728 <recovery-plan-30793.11.5> [class Dr::Recovery::Engine::PrepareVmMasterJob]

2011-12-15T13:12:39.158-05:00 [06532 trivia 'Recovery' ctxID=1a7741a7] Serializing job 'recovery-plan-30793.ipCust-protected-vm-30728-GuestPowerOff'

2011-12-15T13:12:39.190-05:00 [06532 trivia 'Recovery' ctxID=1a7741a7] Job destroyed, name: recovery-plan-30793.ipCust-protected-vm-30728-IPCustomization

2011-12-15T13:12:39.190-05:00 [06532 trivia 'Recovery' ctxID=1a7741a7] Serializing job 'recovery-plan-30793.ipCust-protected-vm-30728'

2011-12-15T13:12:39.596-05:00 [06532 trivia 'Recovery' ctxID=1a7741a7] Running job recovery-plan-30793.ipCust-protected-vm-30728-GuestPowerOff <recovery-plan-30793.11.5.5> [class Dr::Recovery::Engine::PowerOffVmJob]

2011-12-15T13:12:39.596-05:00 [06532 trivia 'Recovery' ctxID=1a7741a7] Initializing job recovery-plan-30793.ipCust-protected-vm-30728-GuestPowerOff <recovery-plan-30793.11.5.5> [class Dr::Recovery::Engine::PowerOffVmJob]

2011-12-15T13:12:39.596-05:00 [06532 info 'Recovery' ctxID=1a7741a7] [recovery-plan-30793.ipCust-protected-vm-30728-GuestPowerOff] Powering off vm ([vim.VirtualMachine:vm-379])

2011-12-15T13:12:39.674-05:00 [04396 verbose 'VmDomain'] Guest shutdown of [vim.VirtualMachine:vm-379] initiated -- waiting on shutdown completion.

2011-12-15T13:12:39.674-05:00 [04396 verbose 'Default' opID=6039cca] Starting async wait for predicate on path "runtime.powerState" of object 'vm-379'.

2011-12-15T13:12:39.674-05:00 [04396 verbose 'LocalVC' opID=6039cca] [PCM] Using token '1025' for pending filter creation

2011-12-15T13:12:39.674-05:00 [04396 verbose 'Default' opID=6039cca] Started async wait for predicate with PropertyMonitor token '1026'.

2011-12-15T13:12:39.674-05:00 [04396 warning 'Default'] The progress of this work handle has been overcomitted. Total child ticks is now 10 out of a possible 1

2011-12-15T13:12:40.158-05:00 [04396 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ASSIGN: items[6], 5274226b-5a44-9564-ffa3-7f8e8be4b182

2011-12-15T13:12:40.158-05:00 [06456 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ASSIGN: items[6], 524e2c29-3653-e238-b613-eb558147e1e9

2011-12-15T13:12:40.158-05:00 [06532 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ASSIGN: items[15], 5238f657-dd1d-0cf7-cd07-dd98e76d4b59

2011-12-15T13:12:40.158-05:00 [06532 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ASSIGN: items[14], 5238f657-dd1d-0cf7-cd07-dd98e76d4b59

2011-12-15T13:13:15.284-05:00 [07040 verbose 'LocalSiteStatus'] Free disk space: 17408 Mb

2011-12-15T13:13:15.284-05:00 [07040 verbose 'LocalSiteStatus'] CPU usage: 13 %

2011-12-15T13:13:15.284-05:00 [07040 verbose 'LocalSiteStatus'] Available memory: 167 Mb

2011-12-15T13:13:33.816-05:00 [03872 verbose 'Default' opID=6039cca] Found a change to object 'vm-379' that matches the condition on which we were waiting

2011-12-15T13:13:33.816-05:00 [03872 verbose 'Default' opID=6039cca] Async wait for predicate succeeded.

2011-12-15T13:13:33.816-05:00 [03872 verbose 'Default' opID=6039cca] Handling completion of the async wait for predicate with PropertyMonitor token '1026'.

2011-12-15T13:13:33.816-05:00 [03872 verbose 'LocalVC' opID=6039cca] [PCM] Destroying filter with filter token '1025'

2011-12-15T13:13:33.816-05:00 [06532 info 'Recovery' ctxID=1a7741a7] [recovery-plan-30793.ipCust-protected-vm-30728-GuestPowerOff] Vm successfully powered off ([vim.VirtualMachine:vm-379])

2011-12-15T13:13:33.816-05:00 [06532 verbose 'Recovery' ctxID=1a7741a7] [recovery-plan-30793.ipCust-protected-vm-30728] Power off after IP Customization succeeded for VM ExchangeFEVM [vm-379]

2011-12-15T13:13:33.831-05:00 [06532 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ASSIGN: items[20], 5238f657-dd1d-0cf7-cd07-dd98e76d4b59

2011-12-15T13:13:33.847-05:00 [06532 trivia 'Recovery' ctxID=1a7741a7] Destroying child job, child: recovery-plan-30793.ipCust-protected-vm-30728-GuestPowerOff <recovery-plan-30793.11.5.5> [class Dr::Recovery::Engine::PowerOffVmJob] parent: recovery-plan-30793.ipCust-protected-vm-30728 <recovery-plan-30793.11.5> [class Dr::Recovery::Engine::PrepareVmMasterJob]

2011-12-15T13:13:33.847-05:00 [06532 error 'Recovery' ctxID=1a7741a7] [recovery-plan-30793.failoverOrchJob] Ip customization failed for VM ExchangeFEVM [vm-379]: (dr.recovery.fault.IPCustomizationFailure) {

--> dynamicType = <unset>,

--> faultCause = (vmodl.MethodFault) null,

--> result = (dr.recovery.CalloutResult) {

--> dynamicType = <unset>,

--> commandLine = "echo "Starting IP customization on Windows ..." >> "%VMware_GuestOp_OutputFile%"

--> cscript "%VMware_GuestOp_File_1%" /MacAddress:00:50:56:9d:04:37 /WINSserver:DELETEALL >> "%VMware_GuestOp_OutputFile%" 2>&1

--> echo Exit code: %ERRORLEVEL% >> "%VMware_GuestOp_OutputFile%"

--> if not %ERRORLEVEL% == 0 exit %ERRORLEVEL%

--> "%VMware_GuestOp_File_0%" setupNic -m 00:50:56:9d:04:37 -s 10.120.187.55 -su 255.255.255.0 >> "%VMware_GuestOp_OutputFile%" 2>&1

--> echo Exit code: %ERRORLEVEL% >> "%VMware_GuestOp_OutputFile%"

--> if not %ERRORLEVEL% == 0 exit %ERRORLEVEL%

--> "%VMware_GuestOp_File_0%" setupNic -m 00:50:56:9d:04:37 -g 10.120.187.1 -gm 1 -d 10.120.187.150 -t 0 >> "%VMware_GuestOp_OutputFile%" 2>&1

--> echo Exit code: %ERRORLEVEL% >> "%VMware_GuestOp_OutputFile%"

--> if not %ERRORLEVEL% == 0 exit %ERRORLEVEL%

--> ping -n 15 127.0.0.1 >nul >> "%VMware_GuestOp_OutputFile%" 2>&1

--> echo Exit code: %ERRORLEVEL% >> "%VMware_GuestOp_OutputFile%"

--> if not %ERRORLEVEL% == 0 exit %ERRORLEVEL%

--> cscript "%VMware_GuestOp_File_1%" /MacAddress:00:50:56:9d:04:37 /Reset:ALLNICS >> "%VMware_GuestOp_OutputFile%" 2>&1

--> echo Exit code: %ERRORLEVEL% >> "%VMware_GuestOp_OutputFile%"

--> if not %ERRORLEVEL% == 0 exit %ERRORLEVEL%

--> type "%TEMP%\vmware-imc\guestcust.log" >> "%VMware_GuestOp_OutputFile%"

--> ",

--> output = "Guest Script Output at: C:\Windows\TEMP\vmware-SYSTEM21

--> "Starting IP customization on Windows ..."

--> Microsoft (R) Windows Script Host Version 5.6

-->

--> MAC Address: 00:50:56:9d:04:37

--> Reset level:

--> Enum script:

--> IP Address:

--> Subnet prefix length:

--> Subnet Address:

--> Gateway:

--> Gateway Metric:

--> DNS server:

--> WINS server: DELETEALL

-->

--> Error: WMI returned 2 adapters for the given MAC address.

--> Exit code: -1

--> ",

--> returnValue = -1,

--> },

--> msg = "",

--> }

2011-12-15T13:13:33.847-05:00 [06532 trivia 'Recovery' ctxID=1a7741a7] Changing recovery site state to: PREPARE_FAILED

2011-12-15T13:13:33.847-05:00 [06532 verbose 'Recovery' ctxID=1a7741a7] [recovery-plan-30793.failoverOrchJob] Setting job failure: (dr.recovery.fault.IPCustomizationFailure) {

--> dynamicType = <unset>,

--> faultCause = (vmodl.MethodFault) null,

--> result = (dr.recovery.CalloutResult) {

--> dynamicType = <unset>,

--> commandLine = "echo "Starting IP customization on Windows ..." >> "%VMware_GuestOp_OutputFile%"

--> cscript "%VMware_GuestOp_File_1%" /MacAddress:00:50:56:9d:04:37 /WINSserver:DELETEALL >> "%VMware_GuestOp_OutputFile%" 2>&1

--> echo Exit code: %ERRORLEVEL% >> "%VMware_GuestOp_OutputFile%"

--> if not %ERRORLEVEL% == 0 exit %ERRORLEVEL%

--> "%VMware_GuestOp_File_0%" setupNic -m 00:50:56:9d:04:37 -s 10.120.187.55 -su 255.255.255.0 >> "%VMware_GuestOp_OutputFile%" 2>&1

--> echo Exit code: %ERRORLEVEL% >> "%VMware_GuestOp_OutputFile%"

--> if not %ERRORLEVEL% == 0 exit %ERRORLEVEL%

--> "%VMware_GuestOp_File_0%" setupNic -m 00:50:56:9d:04:37 -g 10.120.187.1 -gm 1 -d 10.120.187.150 -t 0 >> "%VMware_GuestOp_OutputFile%" 2>&1

--> echo Exit code: %ERRORLEVEL% >> "%VMware_GuestOp_OutputFile%"

--> if not %ERRORLEVEL% == 0 exit %ERRORLEVEL%

--> ping -n 15 127.0.0.1 >nul >> "%VMware_GuestOp_OutputFile%" 2>&1

--> echo Exit code: %ERRORLEVEL% >> "%VMware_GuestOp_OutputFile%"

--> if not %ERRORLEVEL% == 0 exit %ERRORLEVEL%

--> cscript "%VMware_GuestOp_File_1%" /MacAddress:00:50:56:9d:04:37 /Reset:ALLNICS >> "%VMware_GuestOp_OutputFile%" 2>&1

--> echo Exit code: %ERRORLEVEL% >> "%VMware_GuestOp_OutputFile%"

--> if not %ERRORLEVEL% == 0 exit %ERRORLEVEL%

--> type "%TEMP%\vmware-imc\guestcust.log" >> "%VMware_GuestOp_OutputFile%"

--> ",

--> output = "Guest Script Output at: C:\Windows\TEMP\vmware-SYSTEM21

--> "Starting IP customization on Windows ..."

--> Microsoft (R) Windows Script Host Version 5.6

-->

--> MAC Address: 00:50:56:9d:04:37

--> Reset level:

--> Enum script:

--> IP Address:

--> Subnet prefix length:

--> Subnet Address:

--> Gateway:

--> Gateway Metric:

--> DNS server:

--> WINS server: DELETEALL

-->

--> Error: WMI returned 2 adapters for the given MAC address.

--> Exit code: -1

--> ",

--> returnValue = -1,

--> },

--> msg = "",

--> }

2011-12-15T13:13:33.847-05:00 [06532 trivia 'Recovery' ctxID=1a7741a7] Destroying child job, child: recovery-plan-30793.ipCust-protected-vm-30728 <recovery-plan-30793.11.5> [class Dr::Recovery::Engine::PrepareVmMasterJob] parent: recovery-plan-30793.failoverOrchJob <recovery-plan-30793.11> [class Dr::Recovery::Engine::FailoverOrchestratorJob]

2011-12-15T13:13:33.847-05:00 [06532 trivia 'Recovery' ctxID=1a7741a7] Current priority group not yet done; current priority: 25

2011-12-15T13:13:33.862-05:00 [06532 trivia 'Recovery' ctxID=1a7741a7] Setting PVM [dr.replication.ProtectedVm:protected-vm-30728] final state to Error since IP cust. failed

2011-12-15T13:13:33.862-05:00 [06532 info 'Recovery' ctxID=1a7741a7] SetVmState for '[dr.replication.ProtectedVm:protected-vm-30728]' newstate=4

2011-12-15T13:13:33.894-05:00 [06532 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ASSIGN: info.progress, dr.recovery.RecoveryManager.test444

2011-12-15T13:13:33.894-05:00 [06532 trivia 'Recovery' ctxID=1a7741a7] [recovery-plan-30793.failoverOrchJob] NOT YET COMPLETED; # vms done: 1/2, # groups done: 1/1, all priority groups done: 0

2011-12-15T13:13:33.894-05:00 [03556 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ASSIGN: vmStatus, recovery-plan-30793

2011-12-15T13:13:33.894-05:00 [04688 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ASSIGN: vmSettingMappings["protected-vm-30728"].status, recovery-plan-30793

2011-12-15T13:13:33.925-05:00 [04396 trivia 'Recovery'] Found VM setting mappings; planDbId: 0, # of mappings: 2, # of protected VMs in the plan: 2

2011-12-15T13:13:33.925-05:00 [05924 verbose 'SnmpManager'] SNMP trap 'RecoveryVmEndTrap' was sent successfully.

2011-12-15T13:13:34.831-05:00 [04396 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ASSIGN: items[6], 5274226b-5a44-9564-ffa3-7f8e8be4b182

2011-12-15T13:13:34.831-05:00 [04396 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ASSIGN: items[6], 524e2c29-3653-e238-b613-eb558147e1e9

2011-12-15T13:13:34.831-05:00 [04396 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ASSIGN: items[15], 5238f657-dd1d-0cf7-cd07-dd98e76d4b59

2011-12-15T13:13:34.831-05:00 [04396 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ASSIGN: items[14], 5238f657-dd1d-0cf7-cd07-dd98e76d4b59

2011-12-15T13:14:01.191-05:00 [00464 info 'Recovery' ctxID=1a7741a7] [recovery-plan-30793.ipCust-protected-vm-30878-IPCustomization] In-Guest command 'echo "Starting IP customization on Windows ..." >> "%VMware_GuestOp_OutputFile%"

--> cscript "%VMware_GuestOp_File_1%" /MacAddress:00:50:56:b8:1d:2a /WINSserver:DELETEALL >> "%VMware_GuestOp_OutputFile%" 2>&1

--> echo Exit code: %ERRORLEVEL% >> "%VMware_GuestOp_OutputFile%"

--> if not %ERRORLEVEL% == 0 exit %ERRORLEVEL%

--> "%VMware_GuestOp_File_0%" setupNic -m 00:50:56:b8:1d:2a -s 10.120.187.52 -su 255.255.255.0 >> "%VMware_GuestOp_OutputFile%" 2>&1

--> echo Exit code: %ERRORLEVEL% >> "%VMware_GuestOp_OutputFile%"

--> if not %ERRORLEVEL% == 0 exit %ERRORLEVEL%

--> "%VMware_GuestOp_File_0%" setupNic -m 00:50:56:b8:1d:2a -g 10.120.187.1 -gm 1 -d 10.120.187.150 -t 0 >> "%VMware_GuestOp_OutputFile%" 2>&1

--> echo Exit code: %ERRORLEVEL% >> "%VMware_GuestOp_OutputFile%"

--> if not %ERRORLEVEL% == 0 exit %ERRORLEVEL%

--> ping -n 15 127.0.0.1 >nul >> "%VMware_GuestOp_OutputFile%" 2>&1

--> echo Exit code: %ERRORLEVEL% >> "%VMware_GuestOp_OutputFile%"

--> if not %ERRORLEVEL% == 0 exit %ERRORLEVEL%

--> cscript "%VMware_GuestOp_File_1%" /MacAddress:00:50:56:b8:1d:2a /Reset:ALLNICS >> "%VMware_GuestOp_OutputFile%" 2>&1

--> echo Exit code: %ERRORLEVEL% >> "%VMware_GuestOp_OutputFile%"

--> if not %ERRORLEVEL% == 0 exit %ERRORLEVEL%

--> type "%TEMP%\vmware-imc\guestcust.log" >> "%VMware_GuestOp_OutputFile%"

--> ' completed with exit code: -1

2011-12-15T13:14:01.191-05:00 [00464 info 'Recovery' ctxID=1a7741a7] [recovery-plan-30793.ipCust-protected-vm-30878-IPCustomization] Copying guest output from guest path C:\WINDOWS\TEMP\vmware0 to SRM server path C:\Windows\TEMP\vmware-SYSTEM177

2011-12-15T13:14:01.582-05:00 [00464 verbose 'VixVcDomain'] Decrementing host config refcount for VIX Login

2011-12-15T13:14:01.582-05:00 [00464 info 'VixVm-vm-383'] Unsetting VM config for shared secret

2011-12-15T13:14:01.613-05:00 [04508 verbose 'VixVcDomain'] Finishing Host Configuration for shared secret on Host

2011-12-15T13:14:01.613-05:00 [04508 info 'VixVcDomain'] Shared Policy RefCount for host [vim.HostSystem:host-269]: 1

2011-12-15T13:14:01.613-05:00 [04508 verbose 'VixVcDomain'] Updating shared secret refcount on host [vim.HostSystem:host-269] to: 0

2011-12-15T13:14:01.644-05:00 [07100 verbose 'LocalVC'] [PCM] Using token '1026' for pending filter creation

2011-12-15T13:14:04.926-05:00 [06932 verbose 'LocalVC'] [PCM] Destroying filter with filter token '1026'

2011-12-15T13:14:04.926-05:00 [06932 info 'VixVm-vm-383'] Guest Session Done.

2011-12-15T13:14:04.941-05:00 [04396 error 'Recovery' ctxID=1a7741a7] [recovery-plan-30793.ipCust-protected-vm-30878-IPCustomization] Guest command on VM: [vim.VirtualMachine:vm-383] failed with exit code: -1

2011-12-15T13:14:04.941-05:00 [04396 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ASSIGN: items[9], 5238f657-dd1d-0cf7-cd07-dd98e76d4b59

2011-12-15T13:14:04.941-05:00 [04396 warning 'Recovery' ctxID=1a7741a7] [recovery-plan-30793.ipCust-protected-vm-30878-IPCustomization] Guest Operation failed for VM [vim.VirtualMachine:vm-383]

2011-12-15T13:14:04.941-05:00 [04396 error 'Recovery' ctxID=1a7741a7] [recovery-plan-30793.ipCust-protected-vm-30878] IP Customization failed for VM ExchangeVM2 [vm-383]: (dr.recovery.fault.IPCustomizationFailure) {

--> dynamicType = <unset>,

--> faultCause = (vmodl.MethodFault) null,

--> result = (dr.recovery.CalloutResult) {

--> dynamicType = <unset>,

--> commandLine = "echo "Starting IP customization on Windows ..." >> "%VMware_GuestOp_OutputFile%"

--> cscript "%VMware_GuestOp_File_1%" /MacAddress:00:50:56:b8:1d:2a /WINSserver:DELETEALL >> "%VMware_GuestOp_OutputFile%" 2>&1

--> echo Exit code: %ERRORLEVEL% >> "%VMware_GuestOp_OutputFile%"

--> if not %ERRORLEVEL% == 0 exit %ERRORLEVEL%

--> "%VMware_GuestOp_File_0%" setupNic -m 00:50:56:b8:1d:2a -s 10.120.187.52 -su 255.255.255.0 >> "%VMware_GuestOp_OutputFile%" 2>&1

--> echo Exit code: %ERRORLEVEL% >> "%VMware_GuestOp_OutputFile%"

--> if not %ERRORLEVEL% == 0 exit %ERRORLEVEL%

--> "%VMware_GuestOp_File_0%" setupNic -m 00:50:56:b8:1d:2a -g 10.120.187.1 -gm 1 -d 10.120.187.150 -t 0 >> "%VMware_GuestOp_OutputFile%" 2>&1

--> echo Exit code: %ERRORLEVEL% >> "%VMware_GuestOp_OutputFile%"

--> if not %ERRORLEVEL% == 0 exit %ERRORLEVEL%

--> ping -n 15 127.0.0.1 >nul >> "%VMware_GuestOp_OutputFile%" 2>&1

--> echo Exit code: %ERRORLEVEL% >> "%VMware_GuestOp_OutputFile%"

--> if not %ERRORLEVEL% == 0 exit %ERRORLEVEL%

--> cscript "%VMware_GuestOp_File_1%" /MacAddress:00:50:56:b8:1d:2a /Reset:ALLNICS >> "%VMware_GuestOp_OutputFile%" 2>&1

--> echo Exit code: %ERRORLEVEL% >> "%VMware_GuestOp_OutputFile%"

--> if not %ERRORLEVEL% == 0 exit %ERRORLEVEL%

--> type "%TEMP%\vmware-imc\guestcust.log" >> "%VMware_GuestOp_OutputFile%"

--> ",

--> output = "Guest Script Output at: C:\Windows\TEMP\vmware-SYSTEM177

--> "Starting IP customization on Windows ..."

--> Microsoft (R) Windows Script Host Version 5.6

-->

--> MAC Address: 00:50:56:b8:1d:2a

--> Reset level:

--> Enum script:

--> IP Address:

--> Subnet prefix length:

--> Subnet Address:

--> Gateway:

--> Gateway Metric:

--> DNS server:

--> WINS server: DELETEALL

-->

--> Error: WMI returned 2 adapters for the given MAC address.

--> Exit code: -1

--> ",

--> returnValue = -1,

--> },

--> msg = "",

--> }

2011-12-15T13:14:04.941-05:00 [04396 trivia 'Recovery' ctxID=1a7741a7] Destroying child job, child: recovery-plan-30793.ipCust-protected-vm-30878-IPCustomization <recovery-plan-30793.11.4.4> [class Dr::Recovery::Engine::InGuestCommandJob] parent: recovery-plan-30793.ipCust-protected-vm-30878 <recovery-plan-30793.11.4> [class Dr::Recovery::Engine::PrepareVmMasterJob]

2011-12-15T13:14:04.941-05:00 [04396 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ASSIGN: items[10], 5238f657-dd1d-0cf7-cd07-dd98e76d4b59

2011-12-15T13:14:04.941-05:00 [04396 trivia 'Recovery' ctxID=1a7741a7] New job created, name: recovery-plan-30793.ipCust-protected-vm-30878-GuestPowerOff

2011-12-15T13:14:04.941-05:00 [04396 trivia 'Recovery' ctxID=1a7741a7] Adding child job, child: recovery-plan-30793.ipCust-protected-vm-30878-GuestPowerOff <non-persisted> [class Dr::Recovery::Engine::PowerOffVmJob] parent: recovery-plan-30793.ipCust-protected-vm-30878 <recovery-plan-30793.11.4> [class Dr::Recovery::Engine::PrepareVmMasterJob]

2011-12-15T13:14:04.941-05:00 [04396 warning 'Default' ctxID=1a7741a7] The progress of this work handle has been overcomitted. Total child ticks is now 8 out of a possible 7

2011-12-15T13:14:04.941-05:00 [04396 trivia 'Recovery' ctxID=1a7741a7] Commit and yield, job: recovery-plan-30793.ipCust-protected-vm-30878 <recovery-plan-30793.11.4> [class Dr::Recovery::Engine::PrepareVmMasterJob]

2011-12-15T13:14:04.941-05:00 [04396 trivia 'Recovery' ctxID=1a7741a7] Serializing job 'recovery-plan-30793.ipCust-protected-vm-30878-GuestPowerOff'

2011-12-15T13:14:04.957-05:00 [04396 trivia 'Recovery' ctxID=1a7741a7] Job destroyed, name: recovery-plan-30793.ipCust-protected-vm-30878-IPCustomization

2011-12-15T13:14:04.957-05:00 [04396 trivia 'Recovery' ctxID=1a7741a7] Serializing job 'recovery-plan-30793.ipCust-protected-vm-30878'

2011-12-15T13:14:04.988-05:00 [04396 trivia 'Recovery' ctxID=1a7741a7] Running job recovery-plan-30793.ipCust-protected-vm-30878-GuestPowerOff <recovery-plan-30793.11.4.5> [class Dr::Recovery::Engine::PowerOffVmJob]

2011-12-15T13:14:04.988-05:00 [04396 trivia 'Recovery' ctxID=1a7741a7] Initializing job recovery-plan-30793.ipCust-protected-vm-30878-GuestPowerOff <recovery-plan-30793.11.4.5> [class Dr::Recovery::Engine::PowerOffVmJob]

2011-12-15T13:14:04.988-05:00 [04396 info 'Recovery' ctxID=1a7741a7] [recovery-plan-30793.ipCust-protected-vm-30878-GuestPowerOff] Powering off vm ([vim.VirtualMachine:vm-383])

2011-12-15T13:14:05.160-05:00 [06932 verbose 'VmDomain'] Guest shutdown of [vim.VirtualMachine:vm-383] initiated -- waiting on shutdown completion.

2011-12-15T13:14:05.160-05:00 [06932 verbose 'Default' opID=11112ed3] Starting async wait for predicate on path "runtime.powerState" of object 'vm-383'.

2011-12-15T13:14:05.160-05:00 [06932 verbose 'LocalVC' opID=11112ed3] [PCM] Using token '1027' for pending filter creation

2011-12-15T13:14:05.160-05:00 [06932 verbose 'Default' opID=11112ed3] Started async wait for predicate with PropertyMonitor token '1028'.

2011-12-15T13:14:05.160-05:00 [06932 warning 'Default'] The progress of this work handle has been overcomitted. Total child ticks is now 10 out of a possible 1

2011-12-15T13:14:05.957-05:00 [06532 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ASSIGN: items[4], 5274226b-5a44-9564-ffa3-7f8e8be4b182

2011-12-15T13:14:05.957-05:00 [06532 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ASSIGN: items[4], 524e2c29-3653-e238-b613-eb558147e1e9

2011-12-15T13:14:05.957-05:00 [06532 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ASSIGN: items[5], 5238f657-dd1d-0cf7-cd07-dd98e76d4b59

2011-12-15T13:14:05.957-05:00 [06532 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ASSIGN: items[4], 5238f657-dd1d-0cf7-cd07-dd98e76d4b59

2011-12-15T13:14:15.285-05:00 [07100 verbose 'LocalSiteStatus'] Free disk space: 17406 Mb

2011-12-15T13:14:15.285-05:00 [07100 verbose 'LocalSiteStatus'] CPU usage: 9 %

2011-12-15T13:14:15.285-05:00 [07100 verbose 'LocalSiteStatus'] Available memory: 166 Mb

2011-12-15T13:14:36.254-05:00 [04164 info 'Recovery' ctxID=1a7741a7] Viewport aggregation interval: 1000000us

2011-12-15T13:14:36.270-05:00 [04164 trivia 'Recovery' ctxID=1a7741a7] Found VM setting mappings; planDbId: 0, # of mappings: 2, # of protected VMs in the plan: 2

2011-12-15T13:14:36.270-05:00 [04164 trivia 'Recovery' ctxID=1a7741a7] Found VM setting mappings; planDbId: 0, # of mappings: 1, # of protected VMs in the plan: 1

2011-12-15T13:14:36.270-05:00 [04164 verbose 'PlaceholderVmManager' ctxID=1a7741a7] Looking up the VM handler for '[dr.replication.ProtectedVm:protected-vm-25252]' to get it's production VM info.

2011-12-15T13:14:36.270-05:00 [04164 verbose 'PlaceholderVmManager' ctxID=1a7741a7] Getting the ProductionVmInfo for production VM '[vim.VirtualMachine:vm-172]' (named 'LOUEXM') of '[dr.replication.ProtectedVm:protected-vm-25252]'.

2011-12-15T13:14:36.270-05:00 [04164 trivia 'Recovery' ctxID=1a7741a7] Found VM setting mappings; planDbId: 0, # of mappings: 1, # of protected VMs in the plan: 1

2011-12-15T13:14:36.270-05:00 [04164 verbose 'PlaceholderVmManager' ctxID=1a7741a7] Looking up the VM handler for '[dr.replication.ProtectedVm:protected-vm-25359]' to get it's production VM info.

2011-12-15T13:14:36.270-05:00 [04164 verbose 'PlaceholderVmManager' ctxID=1a7741a7] Getting the ProductionVmInfo for production VM '[vim.VirtualMachine:vm-2791]' (named 'ExchangeVM1') of '[dr.replication.ProtectedVm:protected-vm-25359]'.

2011-12-15T13:14:36.270-05:00 [04164 trivia 'Recovery' ctxID=1a7741a7] Found VM setting mappings; planDbId: 0, # of mappings: 2, # of protected VMs in the plan: 2

2011-12-15T13:14:36.317-05:00 [04164 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ASSIGN: visibleRowCount, 528053e5-9b3e-3fa0-12e0-cdbb29c4758e

2011-12-15T13:14:36.317-05:00 [04164 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp REMOVE: items[1], 528053e5-9b3e-3fa0-12e0-cdbb29c4758e

2011-12-15T13:14:36.317-05:00 [04164 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp REMOVE: items[2], 528053e5-9b3e-3fa0-12e0-cdbb29c4758e

2011-12-15T13:14:36.317-05:00 [04164 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp REMOVE: items[3], 528053e5-9b3e-3fa0-12e0-cdbb29c4758e

2011-12-15T13:14:36.317-05:00 [04164 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp REMOVE: items[4], 528053e5-9b3e-3fa0-12e0-cdbb29c4758e

2011-12-15T13:14:36.317-05:00 [04164 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp REMOVE: items[5], 528053e5-9b3e-3fa0-12e0-cdbb29c4758e

2011-12-15T13:14:36.317-05:00 [04164 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp REMOVE: items[6], 528053e5-9b3e-3fa0-12e0-cdbb29c4758e

2011-12-15T13:14:36.317-05:00 [04164 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp REMOVE: items[7], 528053e5-9b3e-3fa0-12e0-cdbb29c4758e

2011-12-15T13:14:36.317-05:00 [04164 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp REMOVE: items[8], 528053e5-9b3e-3fa0-12e0-cdbb29c4758e

2011-12-15T13:14:36.786-05:00 [06532 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ASSIGN: visibleRowCount, 528053e5-9b3e-3fa0-12e0-cdbb29c4758e

2011-12-15T13:14:36.786-05:00 [06532 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ADD: items[1], 528053e5-9b3e-3fa0-12e0-cdbb29c4758e

2011-12-15T13:14:36.786-05:00 [06532 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ADD: items[2], 528053e5-9b3e-3fa0-12e0-cdbb29c4758e

2011-12-15T13:14:36.786-05:00 [06532 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ADD: items[3], 528053e5-9b3e-3fa0-12e0-cdbb29c4758e

2011-12-15T13:14:36.786-05:00 [06532 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ADD: items[4], 528053e5-9b3e-3fa0-12e0-cdbb29c4758e

2011-12-15T13:14:36.786-05:00 [06532 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ADD: items[5], 528053e5-9b3e-3fa0-12e0-cdbb29c4758e

2011-12-15T13:14:36.786-05:00 [06532 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ADD: items[6], 528053e5-9b3e-3fa0-12e0-cdbb29c4758e

2011-12-15T13:14:36.786-05:00 [06532 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ADD: items[7], 528053e5-9b3e-3fa0-12e0-cdbb29c4758e

2011-12-15T13:14:36.786-05:00 [06532 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ADD: items[8], 528053e5-9b3e-3fa0-12e0-cdbb29c4758e

2011-12-15T13:14:38.989-05:00 [06532 info 'DrTask'] Starting task 'dr.recovery.RecoveryHistoryManager.retrieveHistoryWindow446'

2011-12-15T13:14:38.989-05:00 [06532 verbose 'PropertyProvider'] RecordOp ASSIGN: info.progress, dr.recovery.RecoveryHistoryManager.retrieveHistoryWindow446

2011-12-15T13:14:38.989-05:00 [04132 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ASSIGN: info.progress, dr.recovery.RecoveryHistoryManager.retrieveHistoryWindow446

2011-12-15T13:14:39.036-05:00 [04132 verbose 'PropertyProvider' ctxID=1a7741a7] RecordOp ASSIGN: info.progress, dr.recovery.RecoveryHistoryManager.retrieveHistoryWindow446

2011-12-15T13:14:39.036-05:00 [04132 verbose 'DrTask' ctxID=1a7741a7] Task 'dr.recovery.RecoveryHistoryManager.retrieveHistoryWindow446' completed with result: (dr.recovery.RecoveryResult) [