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

Reply via email to