Hi I'm looking for some help on this strangle problem. We are testing Win 7 images on VCL system and sometimes reservation would fail with this error (below). It only happens sometimes for different Win7 images. There is no pattern to the problem.
For some reason Win 7 cannot obtain IP address from DHCP during reservation. But after I get this error and check on the image - it has valid public IP address. In attempt to cure it I have added a patch to Windows.pm module to issue 'ipconfig /release' before 'ipconfig /renew'. I've tested code and it runs OK, but it's not in production yet. Before patch goes to production I would like to ask if someone has/had the same issue with Win 7 images. The error message below. Thank you for your help. -- Dmitri Chebotarov Virtual Computing Lab Systems Engineer, TSD - Ent Servers & Messaging 223 Aquia Building, Ffx, MSN: 1B5 Phone: (703) 993-6175 Fax: (703) 993-3404 Forwarded message: > From: r...@www.vcl.gmu.edu > Date: Thursday, April 19, 2012 3:56:50 > Subject: PROBLEM -- > 9141:9049|new|State.pm|vmguest-vcl12>BC3-4|vmwarewin7-Windows732bitSPSS19creating64-v5|sthomp17 > > reservation failed on vmguest-vcl12: failed to update private IP address > ------------------------------------------------------------------------ > time: 2012-04-19 15:56:27 > caller: State.pm:reservation_failed(213) > ( 0) State.pm, reservation_failed (line: 213) > (-1) new.pm, reserve_computer (line: 894) > (-2) new.pm, process (line: 363) > (-3) vcld, make_new_child (line: 568) > (-4) vcld, main (line: 346) > ------------------------------------------------------------------------ > management node: www.vcl.gmu.edu (http://www.vcl.gmu.edu) > reservation PID: 1191 > parent vcld PID: 30919 > > request ID: 9141 > reservation ID: 9049 > request state/laststate: new/new > request start time: 2012-04-19 15:45:00 > request end time: 2012-04-19 20:00:00 > for imaging: no > log ID: 10048 > > computer: vmguest-vcl12 > computer id: 25 > computer type: virtualmachine > computer eth0 MAC address: 00:50:56:03:51:1c > computer eth1 MAC address: 00:50:56:03:51:1d > computer private IP address: 10.3.6.48 > computer public IP address: 129.174.25.26 > computer in block allocation: no > provisioning module: VCL::Module::Provisioning::VMware::VMware > > vm host: BC3-4 > vm host ID: 2 > vm host computer ID: 8 > vm profile: VMware ESX - network storage > vm profile VM path: /vmfs/volumes/Running-Images > vm profile repository path: 0 > vm profile datastore path: /vmfs/volumes/Image-Library/baseprod > vm profile disk type: networkdisk > > image: vmwarewin7-Windows732bitSPSS19creating64-v5 > image display name: Windows 7 32bit: SPSS 19.0.0 > image ID: 64 > image revision ID: 109 > image size: 61440 MB > use Sysprep: yes > root access: yes > image owner ID: 13 > image owner affiliation: GMUGuest > image revision date created: 2012-03-13 10:42:37 > image revision production: yes > OS module: VCL::Module::OS::Windows::Version_6::7 > image revision comments: Created Default profile > > user: sthomp17 > user name: Steele B Thompson > user ID: 1601 > user affiliation: Mason > ------------------------------------------------------------------------ > RECENT LOG ENTRIES FOR THIS PROCESS: > 2012-04-19 15:55:39|1191|9141:9049|new|utils.pm:run_command(9001)|$? is set > to -1, setting exit status to 0, Perl bug likely encountered > 2012-04-19 > 15:55:47|1191|9141:9049|new|OS.pm:is_ssh_responding(401)|vmguest-vcl12 is > responding to SSH, port 22: open, port 24: closed > 2012-04-19 15:55:47|1191|9141:9049|new|VMware.pm:node_status(969)|VM > vmguest-vcl12 is responding to SSH > 2012-04-19 > 15:55:53|1191|9141:9049|new|OS.pm:get_currentimage_txt_contents(157)|retrieved > currentimage.txt contents from vmguest-vcl12 > 2012-04-19 > 15:55:53|1191|9141:9049|new|OS.pm:get_currentimage_txt_contents(169)|found 8 > lines in currentimage.txt on vmguest-vcl12 > 2012-04-19 > 15:55:53|1191|9141:9049|new|OS.pm:get_current_image_name(197)|retrieved > currentimage.txt contents from vmguest-vcl12 > 2012-04-19 15:55:53|1191|9141:9049|new|OS.pm:get_current_image_name(212)|name > of image currently loaded on vmguest-vcl12: > vmwarewin7-Windows732bitSPSS19creating64-v5 > 2012-04-19 > 15:55:53|1191|9141:9049|new|VMware.pm:node_status(990)|currentimage.txt image > (vmwarewin7-Windows732bitSPSS19creating64-v5) matches requested image name > (vmwarewin7-Windows732bitSPSS19creating64-v5) on VM vmguest-vcl12 > 2012-04-19 > 15:55:58|1191|9141:9049|new|OS.pm:get_vcld_post_load_status(697)|vcld post > load tasks have run on vmguest-vcl12: vcld_post_load=success (Thu Apr 19 > 11:54:08 2012) > 2012-04-19 15:55:58|1191|9141:9049|new|VMware.pm:node_status(1051)|OS module > post_load tasks have been completed on VM vmguest-vcl12 > 2012-04-19 15:55:58|1191|9141:9049|new|new.pm:reload_image(475)|node_status > returned a hash reference > 2012-04-19 15:55:58|1191|9141:9049|new|new.pm:reload_image(480)|node_status > hash reference contains key {status}=READY > 2012-04-19 15:55:58|1191|9141:9049|new|new.pm:reload_image(529)|node_status > returned 'READY', vmguest-vcl12 will not be reloaded > 2012-04-19 15:55:58|1191|9141:9049|new|utils.pm:insertloadlog(3878)|inserted > computer=25, info, node status is READY, vmguest-vcl12 will not be reloaded > 2012-04-19 > 15:55:58|1191|9141:9049|new|utils.pm:update_currentimage(6091)|updating > computer 25: image=64, imagerevision=109 > 2012-04-19 > 15:55:58|1191|9141:9049|new|utils.pm:update_currentimage(6121)|updated > currentimageid and imagerevision id for computer id 25 > 2012-04-19 15:55:58|1191|9141:9049|new|new.pm:reload_image(633)|updated > computer table for vmguest-vcl12: currentimageid=64 > 2012-04-19 15:55:58|1191|9141:9049|new|new.pm:reload_image(640)|returning 1 > 2012-04-19 15:55:58|1191|9141:9049|new|new.pm:process(248)|vmguest-vcl12 is > loaded with vmwarewin7-Windows732bitSPSS19creating64-v5 > 2012-04-19 15:55:58|1191|9141:9049|new|new.pm:process(341)|vmguest-vcl12 next > image is already set to vmwarewin7-Windows732bitSPSS19creating64-v5 > 2012-04-19 > 15:55:58|1191|9141:9049|new|DataStructure.pm:is_parent_reservation(991)|returning > true: parent reservation ID for this request: 9049 > 2012-04-19 > 15:55:58|1191|9141:9049|new|new.pm:reserve_computer(881)|user_standalone=1, > image OS type=windows > 2012-04-19 15:55:58|1191|9141:9049|new|OS.pm:update_public_ip_address(595)|IP > configuration is set to dynamicDHCP, attempting to retrieve dynamic public IP > address from vmguest-vcl12 > 2012-04-19 > 15:56:03|1191|9141:9049|new|OS.pm:is_ssh_responding(401)|vmguest-vcl12 is > responding to SSH, port 22: open, port 24: closed > 2012-04-19 15:56:09|1191|9141:9049|new|Windows.pm:is_64_bit(8108)|32-bit > Windows OS detected, PROCESSOR_IDENTIFIER: x86 Family 6 Model 44 Stepping 2, > GenuineIntel > 2012-04-19 > 15:56:09|1191|9141:9049|new|Windows.pm:get_system32_path(8152)|32-bit Windows > OS installed on vmguest-vcl12, using C:/Windows/System32 > 2012-04-19 > 15:56:09|1191|9141:9049|new|Windows.pm:get_network_configuration(4949)|attempting > to retrieve network configuration information from vmguest-vcl12 > 2012-04-19 > 15:56:09|1191|9141:9049|new|utils.pm:run_ssh_command(5383)|executing SSH > command on vmguest-vcl12: > |1191|9141:9049|new| /usr/bin/ssh -i /etc/vcl/vcl.key -o > StrictHostKeyChecking=no -l root -p 22 -x vmguest-vcl12 > 'C:/Windows/System32/ipconfig.exe /all' 2>&1 > 2012-04-19 > 15:56:14|1191|9141:9049|new|Windows.pm:get_network_configuration(4984)|found > interface: Local Area Connection 3 > 2012-04-19 > 15:56:14|1191|9141:9049|new|Windows.pm:get_network_configuration(4984)|found > interface: Local Area Connection > 2012-04-19 > 15:56:14|1191|9141:9049|new|Windows.pm:get_network_configuration(4984)|found > interface: isatap.vcl.gmu.edu > 2012-04-19 > 15:56:14|1191|9141:9049|new|Windows.pm:get_network_configuration(4984)|found > interface: Teredo Tunneling Pseudo-Interface > 2012-04-19 > 15:56:14|1191|9141:9049|new|Windows.pm:get_network_configuration(5036)|saving > network configuration in $self->{network_configuration} > 2012-04-19 > 15:56:14|1191|9141:9049|new|DataStructure.pm:get_computer_private_ip_address(1581)|attempting > to retrieve private IP address for computer: vmguest-vcl12 > 2012-04-19 > 15:56:14|1191|9141:9049|new|DataStructure.pm:get_computer_private_ip_address(1585)|retrieved > contents of /etc/hosts on this management node, contains 306 lines > 2012-04-19 > 15:56:14|1191|9141:9049|new|DataStructure.pm:get_computer_private_ip_address(1645)|returning > IP address from /etc/hosts file: 10.3.6.48 > 2012-04-19 > 15:56:14|1191|9141:9049|new|Windows.pm:get_network_configuration(5075)|private > interface found: Local Area Connection, description: Intel(R) PRO/1000 MT > Network Connection, address(es): 10.3.6.48 > 2012-04-19 15:56:14|1191|9141:9049|new|utils.pm:is_valid_ip_address(9269)|IP > address is valid: 169.254.196.50 > 2012-04-19 > 15:56:14|1191|9141:9049|new|utils.pm:is_public_ip_address(9399)|reserved IP > address: 169.254.196.50, returning 0 > 2012-04-19 > 15:56:14|1191|9141:9049|new|Windows.pm:get_network_configuration(5117)|interface > found with non-public address not matching private address for reservation: > Local Area Connection 3, address(es): 169.254.196.50 > 2012-04-19 > 15:56:14|1191|9141:9049|new|Windows.pm:get_network_configuration(5124)|interface > will be returned if another with a public address isn't found > |1191|9141:9049|new| ---- WARNING ---- > |1191|9141:9049|new| 2012-04-19 > 15:56:14|1191|9141:9049|new|Windows.pm:get_public_ip_address(5351)|public > interface 'Local Area Connection 3' has DHCP enabled and is assigned an > auto-generated IP address: 169.254.196.50, management node DHCP > configuration: 'dynamicDHCP' > |1191|9141:9049|new| ( 0) Windows.pm, get_public_ip_address (line: 5351) > |1191|9141:9049|new| (-1) OS.pm, update_public_ip_address (line: 600) > |1191|9141:9049|new| (-2) new.pm, reserve_computer (line: 894) > |1191|9141:9049|new| (-3) new.pm, process (line: 363) > |1191|9141:9049|new| (-4) vcld, make_new_child (line: 568) > |1191|9141:9049|new| (-5) vcld, main (line: 346) > 2012-04-19 > 15:56:14|1191|9141:9049|new|utils.pm:run_ssh_command(5383)|executing SSH > command on vmguest-vcl12: > |1191|9141:9049|new| /usr/bin/ssh -i /etc/vcl/vcl.key -o > StrictHostKeyChecking=no -l root -p 22 -x vmguest-vcl12 > 'C:/Windows/System32/ipconfig.exe /renew "Local Area Connection 3"' 2>&1 > 2012-04-19 > 15:56:22|1191|9141:9049|new|utils.pm:run_ssh_command(5467)|run_ssh_command > output: > |1191|9141:9049|new| Windows IP Configuration > |1191|9141:9049|new| An error occurred while renewing interface Local Area > Connection 3 : The requested address is not valid in its context. > 2012-04-19 15:56:22|1191|9141:9049|new|utils.pm:run_ssh_command(5481)|SSH > command executed on vmguest-vcl12, returning (0, "Windows IP Configuration An > er...") > 2012-04-19 15:56:22|1191|9141:9049|new|Windows.pm:ipconfig_renew(5560)|ran > ipconfig /renew > 2012-04-19 > 15:56:22|1191|9141:9049|new|Windows.pm:get_network_configuration(4949)|attempting > to retrieve network configuration information from vmguest-vcl12 > 2012-04-19 > 15:56:22|1191|9141:9049|new|utils.pm:run_ssh_command(5383)|executing SSH > command on vmguest-vcl12: > |1191|9141:9049|new| /usr/bin/ssh -i /etc/vcl/vcl.key -o > StrictHostKeyChecking=no -l root -p 22 -x vmguest-vcl12 > 'C:/Windows/System32/ipconfig.exe /all' 2>&1 > 2012-04-19 > 15:56:27|1191|9141:9049|new|Windows.pm:get_network_configuration(4984)|found > interface: Local Area Connection 3 > 2012-04-19 > 15:56:27|1191|9141:9049|new|Windows.pm:get_network_configuration(4984)|found > interface: Local Area Connection > 2012-04-19 > 15:56:27|1191|9141:9049|new|Windows.pm:get_network_configuration(4984)|found > interface: isatap.vcl.gmu.edu > 2012-04-19 > 15:56:27|1191|9141:9049|new|Windows.pm:get_network_configuration(4984)|found > interface: Teredo Tunneling Pseudo-Interface > 2012-04-19 > 15:56:27|1191|9141:9049|new|Windows.pm:get_network_configuration(5036)|saving > network configuration in $self->{network_configuration} > 2012-04-19 > 15:56:27|1191|9141:9049|new|DataStructure.pm:get_computer_private_ip_address(1557)|returning > private IP address previously retrieved: 10.3.6.48 > 2012-04-19 > 15:56:27|1191|9141:9049|new|Windows.pm:get_network_configuration(5075)|private > interface found: Local Area Connection, description: Intel(R) PRO/1000 MT > Network Connection, address(es): 10.3.6.48 > 2012-04-19 15:56:27|1191|9141:9049|new|utils.pm:is_valid_ip_address(9269)|IP > address is valid: 169.254.196.50 > 2012-04-19 > 15:56:27|1191|9141:9049|new|utils.pm:is_public_ip_address(9399)|reserved IP > address: 169.254.196.50, returning 0 > 2012-04-19 > 15:56:27|1191|9141:9049|new|Windows.pm:get_network_configuration(5117)|interface > found with non-public address not matching private address for reservation: > Local Area Connection 3, address(es): 169.254.196.50 > 2012-04-19 > 15:56:27|1191|9141:9049|new|Windows.pm:get_network_configuration(5124)|interface > will be returned if another with a public address isn't found > |1191|9141:9049|new| ---- WARNING ---- > |1191|9141:9049|new| 2012-04-19 > 15:56:27|1191|9141:9049|new|Windows.pm:get_public_ip_address(5347)|unable to > retrieve public IP address, public interface 'Local Area Connection 3' is > still assigned an auto-generated IP address after attempting 'ipconfig /renew > "Local Area Connection 3"' > |1191|9141:9049|new| ( 0) Windows.pm, get_public_ip_address (line: 5347) > |1191|9141:9049|new| (-1) Windows.pm, get_public_ip_address (line: 5360) > |1191|9141:9049|new| (-2) OS.pm, update_public_ip_address (line: 600) > |1191|9141:9049|new| (-3) new.pm, reserve_computer (line: 894) > |1191|9141:9049|new| (-4) new.pm, process (line: 363) > |1191|9141:9049|new| (-5) vcld, make_new_child (line: 568) > |1191|9141:9049|new| ---- WARNING ---- > |1191|9141:9049|new| 2012-04-19 > 15:56:27|1191|9141:9049|new|OS.pm:update_public_ip_address(608)|failed to > retrieve dynamic public IP address from vmguest-vcl12 > |1191|9141:9049|new| ( 0) OS.pm, update_public_ip_address (line: 608) > |1191|9141:9049|new| (-1) new.pm, reserve_computer (line: 894) > |1191|9141:9049|new| (-2) new.pm, process (line: 363) > |1191|9141:9049|new| (-3) vcld, make_new_child (line: 568) > |1191|9141:9049|new| (-4) vcld, main (line: 346) > 2012-04-19 15:56:27|1191|9141:9049|new|utils.pm:insertloadlog(3878)|inserted > computer=25, dynamicDHCPaddress, failed to retrieve dynamic public IP address > from vmguest-vcl12 > 2012-04-19 > 15:56:27|1191|9141:9049|new|DataStructure.pm:get_computer_state_name(2305)|attempting > to retrieve current state of computer vmguest-vcl12 from the database > 2012-04-19 > 15:56:27|1191|9141:9049|new|DataStructure.pm:get_computer_state_name(2336)|retrieved > current state of computer vmguest-vcl12 from the database: available > 2012-04-19 15:56:27|1191|9141:9049|new|DataStructure.pm:_automethod(834)|data > structure updated: > $self->request_data->{reservation}{9049}{computer}{state}{name} > |1191|9141:9049|new| computer_state_name = available > 2012-04-19 > 15:56:27|1191|9141:9049|new|DataStructure.pm:get_computer_private_ip_address(1557)|returning > private IP address previously retrieved: 10.3.6.48 > 2012-04-19 15:56:27|1191|9141:9049|new|utils.pm:is_inblockrequest(6166)|zero > rows were returned from database select > 2012-04-19 > 15:56:27|1191|9141:9049|new|DataStructure.pm:get_image_affiliation_name(2035)|image > owner id: 13 > 2012-04-19 15:56:27|1191|9141:9049|new|utils.pm:getnewdbh(2712)|database > requested (information_schema) does not match handle stored in $ENV{dbh} > (vcl:localhost) > 2012-04-19 15:56:27|1191|9141:9049|new|utils.pm:getnewdbh(2763)|database > handle stored in $ENV{dbh} > 2012-04-19 > 15:56:27|1191|9141:9049|new|DataStructure.pm:retrieve_user_data(1352)|attempting > to retrieve and store data for user: user.id = '13' > 2012-04-19 15:56:27|1191|9141:9049|new|utils.pm:getnewdbh(2712)|database > requested (vcl) does not match handle stored in $ENV{dbh} > (information_schema:localhost) > 2012-04-19 15:56:27|1191|9141:9049|new|utils.pm:getnewdbh(2763)|database > handle stored in $ENV{dbh} >
