On Thu, Apr 19, 2012 at 7:43 PM, Dmitri Chebotarov <dcheb...@gmu.edu> wrote: > 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.
We are seeing the same problem with our Windows 7/2008 images. The first private network adapter gets installed and obtains an IP address pretty quickly when the computer boots. The computer then begins responding to SSH and vcld continues to perform the post-load steps. It gets tripped up because the 2nd public network adapter isn't installed or initialized yet. I verified this by watching a Windows 2008 VM load. When the root account automatically logged in, I closed the black command boxes from the console in order to prevent root from automatically being logged off. I then ran ipconfig over and over again. The private adapter had an address. Windows was still installing the 2nd adapter (the "installing driver" popups appeared in the system tray). When the 2nd appeared in the ipconfig output it had a 169 address for at least a minute then finally obtained the correct address. The delay between the 1st adapter getting a valid IP address and the 2nd was over 2 minutes. > 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. This should help. Please create a Jira issue and submit a patch. Also, whenever running 'ipconfig /renew' on the public adapter, the DHCP mode of the management node should be checked first to make sure it isn't static: if ($self->data->get_management_node_public_ip_configuration() =~ /static/i) This check isn't in the current code but it should be added. The reason has to do with VCL installations using static public IPs. Windows has a hard-coded 60 second timeout on ipconfig /renew if no DHCP servers respond. This will slow every reservation. I'd also like code added to the wait_for_response subroutine to try to detect if devices are still being installed after the computer responds to SSH. There should be a drvinst.exe process running. The code can check for this and loop until there are no drvinst.exe processes running. This wouldn't guarantee that everything is done being installed. There may be periods in between different devices installs when no drvinst.exe process is running. There may be other ways of detecting when device installation is complete via WMI or by checking the setupapi.log file. Also also, the "failed to update private IP address" message is a typo. It should say "public". This was corrected in trunk a couple months ago. Thanks, Andy > 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} >> > >
