Thanks Andy, I'll try your suggestions tonight and report back. Your help is much appreciated!
Jeff -----Original Message----- From: Andy Kurth [mailto:andy_ku...@ncsu.edu] Sent: Mon 1/25/2010 12:33 PM To: vcl-dev@incubator.apache.org Subject: Re: Issues with Inserting Image Reservation Into VCL DB Hello Jeff, It appears that the image was successfully captured and it's at the point where it's trying to reload the new image. Is the computer.privateIPaddress value set in the database? If not, set this for vcl-winxp in the computer table and see if the warnings go away. You can also add an entry in the /etc/hosts file on the management node for the private address of vcl-winxp. Either of these should clear up most of the warning messages you're seeing. You don't have to go through the entire imaging process again to troubleshoot this. You can restart the reload process by: -Kill the existing vcld process for the reservation if it's still running. The PID to kill is displayed as the leftmost field in the log output (1297 in the output you included). Don't kill the main vcld process. -Set request.state to 'reload', request.start to NOW(), and request.end to some time in the future. The vcld process should begin to process it again. Start 'tail -f /var/log/vcld.log' before changing the request state. Is it hanging indefinitely after it attempts to run the last command (route delete 0.0.0.0) included in the log output? I haven't seen this problem before if it is indeed hanging. The 'route delete' command may be breaking networking on the computer and tripping up the SSH command. I would try running the SSH command manually with the -v option to try to figure out what's happening: ssh -v -i /etc/vcl/vcl.key -l root -p 22 -x vcl-winxp 'route delete 0.0.0.0' If this command hangs, try adding the ServerAliveInterval SSH option: ssh -v -o ServerAliveInterval=15 -i /etc/vcl/vcl.key -l root -p 22 -x vcl-winxp 'route delete 0.0.0.0' Give this command at least 20 seconds before killing it if it hangs. If this prevents it from hanging, try manually running the next command VCL would have performed: ssh -i /etc/vcl/vcl.key -l root -p 22 -x vcl-winxp 'route -p ADD 0.0.0.0 MASK 0.0.0.0 134.154.193.190 METRIC 1' The output of these commands may be helpful in troubleshooting. Regards, Andy Kurth / NCSU VCL Jeffrey Wisman wrote: > Hi all - Just joined this list. I've been working on a pilot VCL install at > CSU East Bay, and am hung up on what seems like nearly the last step. I'm > following instructions at the bottom of this page: > http://cwiki.apache.org/confluence/display/VCL/Create+a+Windows+Base+Image > > I'm attempting to insert the image reservation into the VCL DB, and it only > gets as far as this network/route issue. Is this a DHCP problem? A hosts > file issue? Something else? Please let me know if anyone has seen this > before, or can help troubleshoot. Here is the last part of the output from > tail -f /var/log/vcld.log > > > |1297|11:34|reload| ---- WARNING ---- > |1297|11:34|reload| 2010-01-23 > 00:33:30|1297|11:34|reload|Windows.pm:firewall_enable_ssh_private(4197)|SSH > will not be disabled on public interface because public interface name could > not be determined > |1297|11:34|reload| ( 0) utils.pm, notify (line: 728) > |1297|11:34|reload| (-1) Windows.pm, firewall_enable_ssh_private (line: 4197) > |1297|11:34|reload| (-2) Windows.pm, post_load (line: 485) > |1297|11:34|reload| (-3) new.pm, reload_image (line: 692) > |1297|11:34|reload| (-4) new.pm, process (line: 266) > |1297|11:34|reload| (-5) vcld, make_new_child (line: 594) > |1297|11:34|reload| (-6) vcld, main (line: 341) > > 2010-01-23 > 00:33:30|1297|11:34|reload|Windows.pm:get_network_configuration(4630)|network > configuration has already been retrieved > 2010-01-23 > 00:33:30|1297|11:34|reload|DataStructure.pm:get_computer_private_ip_address(1 > 442)|attempting to retrieve private IP address for computer: vcl-winxp > 2010-01-23 > 00:33:30|1297|11:34|reload|DataStructure.pm:get_computer_private_ip_address(1 > 446)|retrieved contents of /etc/hosts on this management node, contains 6 > lines > > |1297|11:34|reload| ---- WARNING ---- > |1297|11:34|reload| 2010-01-23 > 00:33:30|1297|11:34|reload|DataStructure.pm:get_computer_private_ip_address(1 > 466)|did not find any lines in /etc/hosts containing 'vcl-winxp' > |1297|11:34|reload| ( 0) utils.pm, notify (line: 728) > |1297|11:34|reload| (-1) DataStructure.pm, get_computer_private_ip_address > (line: 1466) > |1297|11:34|reload| (-2) Windows.pm, get_network_configuration (line: 4642) > |1297|11:34|reload| (-3) Windows.pm, get_private_interface_name (line: 4761) > |1297|11:34|reload| (-4) Windows.pm, firewall_enable_ssh_private (line: 4202) > |1297|11:34|reload| (-5) Windows.pm, post_load (line: 485) > |1297|11:34|reload| (-6) new.pm, reload_image (line: 692) > > 2010-01-23 > 00:33:30|1297|11:34|reload|Windows.pm:get_network_configuration(4644)|unable > to retrieve computer private IP address from reservation data > > |1297|11:34|reload| ---- WARNING ---- > |1297|11:34|reload| 2010-01-23 > 00:33:30|1297|11:34|reload|Windows.pm:get_private_interface_name(4763)|unable > to retrieve network configuration > |1297|11:34|reload| ( 0) utils.pm, notify (line: 728) > |1297|11:34|reload| (-1) Windows.pm, get_private_interface_name (line: 4763) > |1297|11:34|reload| (-2) Windows.pm, firewall_enable_ssh_private (line: 4202) > |1297|11:34|reload| (-3) Windows.pm, post_load (line: 485) > |1297|11:34|reload| (-4) new.pm, reload_image (line: 692) > |1297|11:34|reload| (-5) new.pm, process (line: 266) > |1297|11:34|reload| (-6) vcld, make_new_child (line: 594) > > > |1297|11:34|reload| ---- WARNING ---- > |1297|11:34|reload| 2010-01-23 > 00:33:30|1297|11:34|reload|Windows.pm:firewall_enable_ssh_private(4220)|priva > te interface name could not be determined, SSH will be enabled for all > profiles > |1297|11:34|reload| ( 0) utils.pm, notify (line: 728) > |1297|11:34|reload| (-1) Windows.pm, firewall_enable_ssh_private (line: 4220) > |1297|11:34|reload| (-2) Windows.pm, post_load (line: 485) > |1297|11:34|reload| (-3) new.pm, reload_image (line: 692) > |1297|11:34|reload| (-4) new.pm, process (line: 266) > |1297|11:34|reload| (-5) vcld, make_new_child (line: 594) > |1297|11:34|reload| (-6) vcld, main (line: 341) > > 2010-01-23 > 00:33:30|1297|11:34|reload|utils.pm:run_ssh_command(6168)|executing SSH > command on vcl-winxp: > |1297|11:34|reload| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x > vcl-winxp 'netsh.exe firewall set portopening name = "Cygwin SSHD" protocol = > TCP port = 22 profile = ALL' 2>&1 > 2010-01-23 00:33:35|1226|vcld:main(165)|lastcheckin time updated for > management node 1: 2010-01-23 00:33:35 > 2010-01-23 > 00:33:37|1297|11:34|reload|utils.pm:run_ssh_command(6250)|run_ssh_command > output: > |1297|11:34|reload| Ok. > 2010-01-23 00:33:37|1297|11:34|reload|utils.pm:run_ssh_command(6264)|SSH > command executed on vcl-winxp, returning (0, "Ok.") > 2010-01-23 > 00:33:37|1297|11:34|reload|Windows.pm:firewall_enable_ssh_private(4232)|confi > gured firewall to allow SSH on private interface > 2010-01-23 > 00:33:37|1297|11:34|reload|Windows.pm:get_network_configuration(4630)|network > configuration has already been retrieved > 2010-01-23 > 00:33:37|1297|11:34|reload|DataStructure.pm:get_computer_private_ip_address(1 > 442)|attempting to retrieve private IP address for computer: vcl-winxp > 2010-01-23 > 00:33:37|1297|11:34|reload|DataStructure.pm:get_computer_private_ip_address(1 > 446)|retrieved contents of /etc/hosts on this management node, contains 6 > lines > > |1297|11:34|reload| ---- WARNING ---- > |1297|11:34|reload| 2010-01-23 > 00:33:37|1297|11:34|reload|DataStructure.pm:get_computer_private_ip_address(1 > 466)|did not find any lines in /etc/hosts containing 'vcl-winxp' > |1297|11:34|reload| ( 0) utils.pm, notify (line: 728) > |1297|11:34|reload| (-1) DataStructure.pm, get_computer_private_ip_address > (line: 1466) > |1297|11:34|reload| (-2) Windows.pm, get_network_configuration (line: 4642) > |1297|11:34|reload| (-3) Windows.pm, get_public_interface_name (line: 4791) > |1297|11:34|reload| (-4) Windows.pm, firewall_enable_ping_private (line: > 3935) > |1297|11:34|reload| (-5) Windows.pm, post_load (line: 496) > |1297|11:34|reload| (-6) new.pm, reload_image (line: 692) > > 2010-01-23 > 00:33:37|1297|11:34|reload|Windows.pm:get_network_configuration(4644)|unable > to retrieve computer private IP address from reservation data > > |1297|11:34|reload| ---- WARNING ---- > |1297|11:34|reload| 2010-01-23 > 00:33:37|1297|11:34|reload|Windows.pm:get_public_interface_name(4793)|unable > to retrieve network configuration > |1297|11:34|reload| ( 0) utils.pm, notify (line: 728) > |1297|11:34|reload| (-1) Windows.pm, get_public_interface_name (line: 4793) > |1297|11:34|reload| (-2) Windows.pm, firewall_enable_ping_private (line: > 3935) > |1297|11:34|reload| (-3) Windows.pm, post_load (line: 496) > |1297|11:34|reload| (-4) new.pm, reload_image (line: 692) > |1297|11:34|reload| (-5) new.pm, process (line: 266) > |1297|11:34|reload| (-6) vcld, make_new_child (line: 594) > > > |1297|11:34|reload| ---- WARNING ---- > |1297|11:34|reload| 2010-01-23 > 00:33:37|1297|11:34|reload|Windows.pm:firewall_enable_ping_private(3946)|ping > will not be disabled on public interface because public interface name could > not be determined > |1297|11:34|reload| ( 0) utils.pm, notify (line: 728) > |1297|11:34|reload| (-1) Windows.pm, firewall_enable_ping_private (line: > 3946) > |1297|11:34|reload| (-2) Windows.pm, post_load (line: 496) > |1297|11:34|reload| (-3) new.pm, reload_image (line: 692) > |1297|11:34|reload| (-4) new.pm, process (line: 266) > |1297|11:34|reload| (-5) vcld, make_new_child (line: 594) > |1297|11:34|reload| (-6) vcld, main (line: 341) > > 2010-01-23 > 00:33:37|1297|11:34|reload|Windows.pm:get_network_configuration(4630)|network > configuration has already been retrieved > 2010-01-23 > 00:33:37|1297|11:34|reload|DataStructure.pm:get_computer_private_ip_address(1 > 442)|attempting to retrieve private IP address for computer: vcl-winxp > 2010-01-23 > 00:33:37|1297|11:34|reload|DataStructure.pm:get_computer_private_ip_address(1 > 446)|retrieved contents of /etc/hosts on this management node, contains 6 > lines > > |1297|11:34|reload| ---- WARNING ---- > |1297|11:34|reload| 2010-01-23 > 00:33:37|1297|11:34|reload|DataStructure.pm:get_computer_private_ip_address(1 > 466)|did not find any lines in /etc/hosts containing 'vcl-winxp' > |1297|11:34|reload| ( 0) utils.pm, notify (line: 728) > |1297|11:34|reload| (-1) DataStructure.pm, get_computer_private_ip_address > (line: 1466) > |1297|11:34|reload| (-2) Windows.pm, get_network_configuration (line: 4642) > |1297|11:34|reload| (-3) Windows.pm, get_private_interface_name (line: 4761) > |1297|11:34|reload| (-4) Windows.pm, firewall_enable_ping_private (line: > 3951) > |1297|11:34|reload| (-5) Windows.pm, post_load (line: 496) > |1297|11:34|reload| (-6) new.pm, reload_image (line: 692) > > 2010-01-23 > 00:33:37|1297|11:34|reload|Windows.pm:get_network_configuration(4644)|unable > to retrieve computer private IP address from reservation data > > |1297|11:34|reload| ---- WARNING ---- > |1297|11:34|reload| 2010-01-23 > 00:33:37|1297|11:34|reload|Windows.pm:get_private_interface_name(4763)|unable > to retrieve network configuration > |1297|11:34|reload| ( 0) utils.pm, notify (line: 728) > |1297|11:34|reload| (-1) Windows.pm, get_private_interface_name (line: 4763) > |1297|11:34|reload| (-2) Windows.pm, firewall_enable_ping_private (line: > 3951) > |1297|11:34|reload| (-3) Windows.pm, post_load (line: 496) > |1297|11:34|reload| (-4) new.pm, reload_image (line: 692) > |1297|11:34|reload| (-5) new.pm, process (line: 266) > |1297|11:34|reload| (-6) vcld, make_new_child (line: 594) > > > |1297|11:34|reload| ---- WARNING ---- > |1297|11:34|reload| 2010-01-23 > 00:33:37|1297|11:34|reload|Windows.pm:firewall_enable_ping_private(3967)|priv > ate interface name could not be determined, ping will be enabled for all > profiles > |1297|11:34|reload| ( 0) utils.pm, notify (line: 728) > |1297|11:34|reload| (-1) Windows.pm, firewall_enable_ping_private (line: > 3967) > |1297|11:34|reload| (-2) Windows.pm, post_load (line: 496) > |1297|11:34|reload| (-3) new.pm, reload_image (line: 692) > |1297|11:34|reload| (-4) new.pm, process (line: 266) > |1297|11:34|reload| (-5) vcld, make_new_child (line: 594) > |1297|11:34|reload| (-6) vcld, main (line: 341) > > 2010-01-23 > 00:33:37|1297|11:34|reload|utils.pm:run_ssh_command(6168)|executing SSH > command on vcl-winxp: > |1297|11:34|reload| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x > vcl-winxp 'netsh.exe firewall set icmpsetting type = 8 mode = ENABLE profile > = ALL ;' 2>&1 > 2010-01-23 00:33:40|1226|vcld:main(165)|lastcheckin time updated for > management node 1: 2010-01-23 00:33:40 > 2010-01-23 > 00:33:43|1297|11:34|reload|utils.pm:run_ssh_command(6250)|run_ssh_command > output: > |1297|11:34|reload| Ok. > 2010-01-23 00:33:43|1297|11:34|reload|utils.pm:run_ssh_command(6264)|SSH > command executed on vcl-winxp, returning (0, "Ok.") > 2010-01-23 > 00:33:43|1297|11:34|reload|Windows.pm:firewall_enable_ping_private(3979)|conf > igured firewall to allow ping on private interface > 2010-01-23 > 00:33:43|1297|11:34|reload|Windows.pm:get_public_default_gateway(4890)|IP > configuration mode in use: dynamicDHCP > 2010-01-23 > 00:33:43|1297|11:34|reload|Windows.pm:get_network_configuration(4630)|network > configuration has already been retrieved > 2010-01-23 > 00:33:43|1297|11:34|reload|DataStructure.pm:get_computer_private_ip_address(1 > 442)|attempting to retrieve private IP address for computer: vcl-winxp > 2010-01-23 > 00:33:43|1297|11:34|reload|DataStructure.pm:get_computer_private_ip_address(1 > 446)|retrieved contents of /etc/hosts on this management node, contains 6 > lines > > |1297|11:34|reload| ---- WARNING ---- > |1297|11:34|reload| 2010-01-23 > 00:33:43|1297|11:34|reload|DataStructure.pm:get_computer_private_ip_address(1 > 466)|did not find any lines in /etc/hosts containing 'vcl-winxp' > |1297|11:34|reload| ( 0) utils.pm, notify (line: 728) > |1297|11:34|reload| (-1) DataStructure.pm, get_computer_private_ip_address > (line: 1466) > |1297|11:34|reload| (-2) Windows.pm, get_network_configuration (line: 4642) > |1297|11:34|reload| (-3) Windows.pm, get_public_default_gateway (line: 4894) > |1297|11:34|reload| (-4) Windows.pm, set_public_default_route (line: 7429) > |1297|11:34|reload| (-5) Windows.pm, post_load (line: 507) > |1297|11:34|reload| (-6) new.pm, reload_image (line: 692) > > 2010-01-23 > 00:33:43|1297|11:34|reload|Windows.pm:get_network_configuration(4644)|unable > to retrieve computer private IP address from reservation data > > |1297|11:34|reload| ---- WARNING ---- > |1297|11:34|reload| 2010-01-23 > 00:33:43|1297|11:34|reload|Windows.pm:get_public_default_gateway(4908)|unable > to retrieve public network configuration currently in use on vcl-winxp > |1297|11:34|reload| ( 0) utils.pm, notify (line: 728) > |1297|11:34|reload| (-1) Windows.pm, get_public_default_gateway (line: 4908) > |1297|11:34|reload| (-2) Windows.pm, set_public_default_route (line: 7429) > |1297|11:34|reload| (-3) Windows.pm, post_load (line: 507) > |1297|11:34|reload| (-4) new.pm, reload_image (line: 692) > |1297|11:34|reload| (-5) new.pm, process (line: 266) > |1297|11:34|reload| (-6) vcld, make_new_child (line: 594) > > 2010-01-23 > 00:33:43|1297|11:34|reload|DataStructure.pm:get_management_node_public_defaul > t_gateway(1783)|returning default gateway from route command: 134.154.193.190 > 2010-01-23 > 00:33:43|1297|11:34|reload|Windows.pm:get_public_default_gateway(4917)|return > ing management node's default gateway address: 134.154.193.190 > 2010-01-23 > 00:33:43|1297|11:34|reload|utils.pm:run_ssh_command(6168)|executing SSH > command on vcl-winxp: > |1297|11:34|reload| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x > vcl-winxp 'route delete 0.0.0.0' 2>&1 > 2010-01-23 00:33:45|1226|vcld:main(165)|lastcheckin time updated for > management node 1: 2010-01-23 00:33:45 > 2010-01-23 00:33:50|1226|vcld:main(165)|lastcheckin time updated for > management node 1: 2010-01-23 00:33:50 > 2010-01-23 00:33:55|1226|vcld:main(165)|lastcheckin time updated for > management node 1: 2010-01-23 00:33:55 > 2010-01-23 00:34:00|1226|vcld:main(165)|lastcheckin time updated for > management node 1: 2010-01-23 00:34:00 > 2010-01-23 00:34:05|1226|vcld:main(165)|lastcheckin time updated for > management node 1: 2010-01-23 00:34:05 > 2010-01-23 00:34:10|1226|vcld:main(165)|lastcheckin time updated for > management node 1: 2010-01-23 00:34:10 > > > > > > > And the database state: > > mysql> select * from request; > +----+---------+--------+-------------+-------+------------+------+---------+ > ---------------------+---------------------+---------------------+----------- > ---+ > | id | stateid | userid | laststateid | logid | forimaging | test | preload | > start | end | daterequested | > datemodified | > +----+---------+--------+-------------+-------+------------+------+---------+ > ---------------------+---------------------+---------------------+----------- > ---+ > | 11 | 14 | 2 | 19 | 0 | 0 | 0 | 0 | > 2010-01-23 00:31:59 | 2010-01-23 01:01:59 | 2010-01-23 00:31:59 | NULL > | > +----+---------+--------+-------------+-------+------------+------+---------+ > ---------------------+---------------------+---------------------+----------- > ---+ > 1 row in set (0.00 sec) > > mysql> select * from reservation; > +----+-----------+------------+---------+-----------------+------------------ > +----------+---------------------+------+ > | id | requestid | computerid | imageid | imagerevisionid | managementnodeid > | remoteIP | lastcheck | pw | > +----+-----------+------------+---------+-----------------+------------------ > +----------+---------------------+------+ > | 34 | 11 | 13 | 10 | 10 | 1 > | NULL | 0000-00-00 00:00:00 | NULL | > +----+-----------+------------+---------+-----------------+------------------ > +----------+---------------------+------+ > 1 row in set (0.00 sec) > > > And finally, here is the directory structure (after executing the commands) > of the VMWare server: > /vmfs/volumes/4ae7602f-490f0fcb-52ef-00144fd1e4ed # ls -l > drwxr-xr-x 1 root root 420 Jan 23 08:31 golden > drwxr-xr-x 1 root root 420 Jan 23 08:31 inuse > drwxr-xr-x 1 root root 4340 Dec 3 18:30 > vcl.csueastbay.edu > drwxr-xr-x 1 root root 4340 Dec 3 18:08 > vcldb.csueastbay.edu > drwxr-xr-x 1 root root 4340 Dec 3 18:23 > vclmgmt.csueastbay.edu > drwxr-xr-x 1 root root 2660 Jan 23 08:22 > vmwarewinxp-base7-v0 > /vmfs/volumes/4ae7602f-490f0fcb-52ef-00144fd1e4ed # cd golden/ > /vmfs/volumes/4ae7602f-490f0fcb-52ef-00144fd1e4ed/golden # ls -l > drwxr-xr-x 1 root root 280 Jan 23 08:31 > vmwarewinxp-base7-v0 > /vmfs/volumes/4ae7602f-490f0fcb-52ef-00144fd1e4ed/golden # cd .. > /vmfs/volumes/4ae7602f-490f0fcb-52ef-00144fd1e4ed # cd inuse/ > /vmfs/volumes/4ae7602f-490f0fcb-52ef-00144fd1e4ed/inuse # ls -l > drwxr-xr-x 1 root root 420 Jan 23 08:31 vcl-winxp > > > Let me know if more output from the logs would be helpful, or any other > information. > > > Thanks, > Jeff Wisman > -- Andy Kurth Virtual Computing Lab Office of Information Technology North Carolina State University andy_ku...@ncsu.edu 919.513.4090
