I have seen this before. For some reason, the firewall isn't enabled
by default for new Windows 2003 installations and the firewall
services aren't running. Enable the firewall via the Control Panel.
Make sure TCP port 22 is open and that SSH is still working and then
restart the capture process.
Don't rerun 'vcld -setup' once you have run it once for a given base
image because it will result in extra unnecessary image entries in the
database. Instead, manually change the request table in the database.
Find the imaging request that was created by 'vcld -setup'. The
request.state value will be 10 (maintenance) and request.laststate
will be 16 (image). change request.state to 16 and the normal running
vcld process will restart the capture.
-Andy
On Tue, Dec 27, 2011 at 3:11 PM, Evelio Quiros <evq...@fiu.edu> wrote:
> Hello,
>
> Happy New Year to you all.
>
> I am having trouble capturing a Windows 2003 Server image. I setup Windows
> 2003 on the VM server and installed and configured Cygwin.
> I setup the gen-keys, and my Management node can SSH to the server fine
> without a password.
> When I tried to capture the new base image, it begins the process, and a
> little while later it reports having failed.
>
> I had been able to capture a linux image and a windows XP base image without
> any trouble, so I know VCL itself is working ok.
>
> Any ideas on what might be wrong ?
>
> Included below is the last part of the vcl log….
>
> 2011-12-27
> 14:42:28|16120|34:34|image|Module.pm:code_loop_timeout(759)|attempt 9:
> waiting for vclimg12 to respond to SSH
> 2011-12-27 14:42:34|13511|vcld:main(167)|lastcheckin time updated for
> management node 1: 2011-12-27 14:42:34
> 2011-12-27 14:42:41|16120|34:34|image|OS.pm:is_ssh_responding(401)|vclimg12
> is responding to SSH, port 22: open, port 24: closed
> 2011-12-27
> 14:42:41|16120|34:34|image|Module.pm:code_loop_timeout(762)|waiting for
> vclimg12 to respond to SSH, code returned true
> 2011-12-27 14:42:41|16120|34:34|image|Windows.pm:reboot(3454)|vclimg12
> responded to ssh
> 2011-12-27 14:42:41|16120|34:34|image|Windows.pm:reboot(3471)|reboot
> complete on vclimg12, took 318 seconds
> 2011-12-27
> 14:42:41|16120|34:34|image|Windows.pm:disable_pagefile(2077)|computer was
> rebooted after disabling pagefile in the registry
> 2011-12-27
> 14:42:41|16120|34:34|image|utils.pm:run_ssh_command(5380)|executing SSH
> command on vclimg12:
> |16120|34:34|image| /usr/bin/ssh -i /etc/vcl/vcl.key -o
> StrictHostKeyChecking=no -l root -p 22 -x vclimg12 'for i in `ls /cygdrive
> 2>/dev/null`; do echo $i; done;' 2>&1
> 2011-12-27
> 14:42:42|16120|34:34|image|Windows.pm:get_volume_list(7958)|retrieved drive
> letter list under /cygdrive:
> |16120|34:34|image| c
> 2011-12-27 14:42:45|16120|34:34|image|Windows.pm:file_exists(1340)|file
> exists on vclimg12: 'c:/pagefile.sys'
> 2011-12-27
> 14:42:45|16120|34:34|image|Windows.pm:delete_file(1102)|attempting to delete
> file: 'c:/pagefile.sys'
> 2011-12-27 14:43:32|16120|34:34|image|Windows.pm:file_exists(1336)|file does
> NOT exist on vclimg12: 'c:/pagefile.sys'
> 2011-12-27 14:43:32|16120|34:34|image|Windows.pm:delete_file(1157)|deleted
> file: 'c:/pagefile.sys'
> 2011-12-27
> 14:43:32|16120|34:34|image|Windows.pm:disable_pagefile(2094)|deleted
> pagefile.sys on all c:
> 2011-12-27
> 14:43:32|16120|34:34|image|Windows.pm:get_network_configuration(5040)|network
> configuration has already been retrieved
> 2011-12-27
> 14:43:32|16120|34:34|image|DataStructure.pm:get_computer_private_ip_address(1557)|returning
> private IP address previously retrieved: 10.0.0.42
> 2011-12-27
> 14:43:32|16120|34:34|image|Windows.pm:get_network_configuration(5075)|private
> interface found: Local Area Connection, description: Intel(R) PRO/1000 MT
> Network Connection, address(es): 10.0.0.42
> 2011-12-27
> 14:43:32|16120|34:34|image|Windows.pm:get_private_interface_name(5177)|returning
> private interface name: Local Area Connection
> 2011-12-27
> 14:43:32|16120|34:34|image|Windows.pm:firewall_disable_rdp(4856)|RDP will be
> disabled on private interface: Local Area Connection
> 2011-12-27
> 14:43:32|16120|34:34|image|Windows.pm:get_network_configuration(5040)|network
> configuration has already been retrieved
> 2011-12-27
> 14:43:32|16120|34:34|image|DataStructure.pm:get_computer_private_ip_address(1557)|returning
> private IP address previously retrieved: 10.0.0.42
> 2011-12-27
> 14:43:32|16120|34:34|image|Windows.pm:get_network_configuration(5075)|private
> interface found: Local Area Connection, description: Intel(R) PRO/1000 MT
> Network Connection, address(es): 10.0.0.42
> 2011-12-27 14:43:32|16120|34:34|image|utils.pm:is_valid_ip_address(9266)|IP
> address is valid: 10.106.128.49
> 2011-12-27
> 14:43:32|16120|34:34|image|utils.pm:is_public_ip_address(9375)|private IP
> address: 10.106.128.49, returning 0
> 2011-12-27
> 14:43:32|16120|34:34|image|Windows.pm:get_network_configuration(5117)|interface
> found with non-public address not matching private address for reservation:
> Local Area Connection 2, address(es): 10.106.128.49
> 2011-12-27
> 14:43:32|16120|34:34|image|Windows.pm:get_network_configuration(5124)|interface
> will be returned if another with a public address isn't found
> 2011-12-27
> 14:43:32|16120|34:34|image|Windows.pm:get_public_interface_name(5207)|returning
> public interface name: Local Area Connection 2
> 2011-12-27
> 14:43:32|16120|34:34|image|Windows.pm:firewall_disable_rdp(4872)|RDP will be
> disabled on public interface: Local Area Connection 2
> 2011-12-27
> 14:43:32|16120|34:34|image|utils.pm:run_ssh_command(5380)|executing SSH
> command on vclimg12:
> |16120|34:34|image| /usr/bin/ssh -i /etc/vcl/vcl.key -o
> StrictHostKeyChecking=no -l root -p 22 -x vclimg12
> 'C:/Windows/System32/netsh.exe firewall delete portopening protocol = TCP
> port = 3389 interface = "Local Area Connection"
> ;C:/Windows/System32/netsh.exe firewall delete portopening protocol = TCP
> port = 3389 interface = "Local Area Connection 2"
> ;C:/Windows/System32/netsh.exe firewall delete portopening protocol = TCP
> port = 3389 profile = ALL' 2>&1
> 2011-12-27
> 14:43:34|16120|34:34|image|utils.pm:run_ssh_command(5464)|run_ssh_command
> output:
> |16120|34:34|image| Ok.
> |16120|34:34|image| Ok.
> |16120|34:34|image| Ok.
> 2011-12-27 14:43:34|16120|34:34|image|utils.pm:run_ssh_command(5478)|SSH
> command executed on vclimg12, returning (0, "Ok. Ok. Ok.")
> 2011-12-27
> 14:43:34|16120|34:34|image|Windows.pm:firewall_disable_rdp(4893)|configured
> firewall to disallow RDP
> 2011-12-27
> 14:43:34|16120|34:34|image|Windows.pm:get_network_configuration(5040)|network
> configuration has already been retrieved
> 2011-12-27
> 14:43:34|16120|34:34|image|DataStructure.pm:get_computer_private_ip_address(1557)|returning
> private IP address previously retrieved: 10.0.0.42
> 2011-12-27
> 14:43:34|16120|34:34|image|Windows.pm:get_network_configuration(5075)|private
> interface found: Local Area Connection, description: Intel(R) PRO/1000 MT
> Network Connection, address(es): 10.0.0.42
> 2011-12-27 14:43:34|16120|34:34|image|utils.pm:is_valid_ip_address(9266)|IP
> address is valid: 10.106.128.49
> 2011-12-27
> 14:43:34|16120|34:34|image|utils.pm:is_public_ip_address(9375)|private IP
> address: 10.106.128.49, returning 0
> 2011-12-27
> 14:43:34|16120|34:34|image|Windows.pm:get_network_configuration(5117)|interface
> found with non-public address not matching private address for reservation:
> Local Area Connection 2, address(es): 10.106.128.49
> 2011-12-27
> 14:43:34|16120|34:34|image|Windows.pm:get_network_configuration(5124)|interface
> will be returned if another with a public address isn't found
> 2011-12-27
> 14:43:34|16120|34:34|image|Windows.pm:get_public_interface_name(5207)|returning
> public interface name: Local Area Connection 2
> 2011-12-27
> 14:43:34|16120|34:34|image|Windows.pm:firewall_enable_ssh(4529)|SSH will be
> disabled on public interface: Local Area Connection 2
> 2011-12-27
> 14:43:34|16120|34:34|image|Windows.pm:get_network_configuration(5040)|network
> configuration has already been retrieved
> 2011-12-27
> 14:43:34|16120|34:34|image|DataStructure.pm:get_computer_private_ip_address(1557)|returning
> private IP address previously retrieved: 10.0.0.42
> 2011-12-27
> 14:43:34|16120|34:34|image|Windows.pm:get_network_configuration(5075)|private
> interface found: Local Area Connection, description: Intel(R) PRO/1000 MT
> Network Connection, address(es): 10.0.0.42
> 2011-12-27
> 14:43:34|16120|34:34|image|Windows.pm:get_private_interface_name(5177)|returning
> private interface name: Local Area Connection
> 2011-12-27
> 14:43:34|16120|34:34|image|Windows.pm:firewall_enable_ssh(4545)|SSH will be
> disabled on private interface: Local Area Connection
> 2011-12-27
> 14:43:34|16120|34:34|image|utils.pm:run_ssh_command(5380)|executing SSH
> command on vclimg12:
> |16120|34:34|image| /usr/bin/ssh -i /etc/vcl/vcl.key -o
> StrictHostKeyChecking=no -l root -p 22 -x vclimg12
> 'C:/Windows/System32/netsh.exe firewall delete portopening protocol = TCP
> port = 22 interface = "Local Area Connection 2"
> ;C:/Windows/System32/netsh.exe firewall delete portopening protocol = TCP
> port = 22 interface = "Local Area Connection" ;C:/Windows/System32/netsh.exe
> firewall set portopening name = "Cygwin SSHD" protocol = TCP port = 22 mode
> = ENABLE scope = ALL' 2>&1
> 2011-12-27 14:43:34|13511|vcld:main(167)|lastcheckin time updated for
> management node 1: 2011-12-27 14:43:34
> 2011-12-27
> 14:43:36|16120|34:34|image|utils.pm:run_ssh_command(5464)|run_ssh_command
> output:
> |16120|34:34|image| Ok.
> |16120|34:34|image| Ok.
> |16120|34:34|image| The service has not been started.
> 2011-12-27 14:43:36|16120|34:34|image|utils.pm:run_ssh_command(5474)|SSH
> command executed on vclimg12, command:
> |16120|34:34|image| /usr/bin/ssh -i /etc/vcl/vcl.key -o
> StrictHostKeyChecking=no -l root -p 22 -x vclimg12
> 'C:/Windows/System32/netsh.exe firewall delete portopening protocol = TCP
> port = 22 interface = "Local Area Connection 2"
> ;C:/Windows/System32/netsh.exe firewall delete portopening protocol = TCP
> port = 22 interface = "Local Area Connection" ;C:/Windows/System32/netsh.exe
> firewall set portopening name = "Cygwin SSHD" protocol = TCP port = 22 mode
> = ENABLE scope = ALL' 2>&1
> |16120|34:34|image| returning (1, "Ok. Ok. The service has not be...")
> |16120|34:34|image| ---- WARNING ----
> |16120|34:34|image| 2011-12-27
> 14:43:36|16120|34:34|image|Windows.pm:firewall_enable_ssh(4579)|failed to
> configure firewall to allow SSH from all addresses, exit status: 1, output:
> |16120|34:34|image| Ok. Ok. The service has not been started.
> |16120|34:34|image| ( 0) Windows.pm, firewall_enable_ssh (line: 4579)
> |16120|34:34|image| (-1) Windows.pm, pre_capture (line: 507)
> |16120|34:34|image| (-2) Version_5.pm, pre_capture (line: 105)
> |16120|34:34|image| (-3) VMware.pm, capture (line: 556)
> |16120|34:34|image| (-4) image.pm, process (line: 162)
> |16120|34:34|image| (-5) vcld, make_new_child (line: 568)
> |16120|34:34|image| ---- WARNING ----
> |16120|34:34|image| 2011-12-27
> 14:43:36|16120|34:34|image|Windows.pm:pre_capture(508)|unable to enable SSH
> from any IP address
> |16120|34:34|image| ( 0) Windows.pm, pre_capture (line: 508)
> |16120|34:34|image| (-1) Version_5.pm, pre_capture (line: 105)
> |16120|34:34|image| (-2) VMware.pm, capture (line: 556)
> |16120|34:34|image| (-3) image.pm, process (line: 162)
> |16120|34:34|image| (-4) vcld, make_new_child (line: 568)
> |16120|34:34|image| (-5) vcld, main (line: 346)
> |16120|34:34|image| ---- WARNING ----
> |16120|34:34|image| 2011-12-27
> 14:43:36|16120|34:34|image|Version_5.pm:pre_capture(109)|failed to execute
> parent class pre_capture() subroutine
> |16120|34:34|image| ( 0) Version_5.pm, pre_capture (line: 109)
> |16120|34:34|image| (-1) VMware.pm, capture (line: 556)
> |16120|34:34|image| (-2) image.pm, process (line: 162)
> |16120|34:34|image| (-3) vcld, make_new_child (line: 568)
> |16120|34:34|image| (-4) vcld, main (line: 346)
> |16120|34:34|image| ---- WARNING ----
> |16120|34:34|image| 2011-12-27
> 14:43:36|16120|34:34|image|VMware.pm:capture(557)|failed to complete OS
> module's pre_capture tasks
> |16120|34:34|image| ( 0) VMware.pm, capture (line: 557)
> |16120|34:34|image| (-1) image.pm, process (line: 162)
> |16120|34:34|image| (-2) vcld, make_new_child (line: 568)
> |16120|34:34|image| (-3) vcld, main (line: 346)
> |16120|34:34|image| ---- WARNING ----
> |16120|34:34|image| 2011-12-27
> 14:43:36|16120|34:34|image|image.pm:process(166)|vmwarewin2003-base2k312-v0
> image failed to be captured by provisioning module
> |16120|34:34|image| ( 0) image.pm, process (line: 166)
> |16120|34:34|image| (-1) vcld, make_new_child (line: 568)
> |16120|34:34|image| (-2) vcld, main (line: 346)
> 2011-12-27
> 14:43:36|16120|34:34|image|DataStructure.pm:get_computer_private_ip_address(1557)|returning
> private IP address previously retrieved: 10.0.0.42
> 2011-12-27 14:43:36|16120|34:34|image|utils.pm:is_inblockrequest(6163)|zero
> rows were returned from database select
> 2011-12-27
> 14:43:36|16120|34:34|image|DataStructure.pm:get_image_affiliation_name(2035)|image
> owner id: 1
> 2011-12-27 14:43:36|16120|34:34|image|utils.pm:getnewdbh(2709)|database
> requested (information_schema) does not match handle stored in $ENV{dbh}
> (vcl:vcldb.fiu.edu)
> 2011-12-27 14:43:36|16120|34:34|image|utils.pm:getnewdbh(2760)|database
> handle stored in $ENV{dbh}
> 2011-12-27
> 14:43:36|16120|34:34|image|DataStructure.pm:retrieve_user_data(1352)|attempting
> to retrieve and store data for user: user.id = '1'
> 2011-12-27 14:43:36|16120|34:34|image|utils.pm:getnewdbh(2709)|database
> requested (vcl) does not match handle stored in $ENV{dbh}
> (information_schema:vcldb.fiu.edu)
> 2011-12-27 14:43:36|16120|34:34|image|utils.pm:getnewdbh(2760)|database
> handle stored in $ENV{dbh}
> 2011-12-27
> 14:43:36|16120|34:34|image|DataStructure.pm:retrieve_user_data(1415)|data
> has been retrieved for user: admin (id: 1)
> 2011-12-27 14:43:37|16120|34:34|image|utils.pm:mail(1255)|SUCCESS -- Sending
> mail To: evq...@fiu.edu, PROBLEM --
> 34:34|image|image.pm|vclimg12>idp01.fiu.edu|vmwarewin2003-base2k312-v0|admin
> |16120|34:34|image| ---- CRITICAL ----
> |16120|34:34|image| 2011-12-27
> 14:43:36|16120|34:34|image|image.pm:reservation_failed(385)|vmwarewin2003-base2k312-v0
> image creation failed
> |16120|34:34|image| ( 0) image.pm, reservation_failed (line: 385)
> |16120|34:34|image| (-1) image.pm, process (line: 167)
> |16120|34:34|image| (-2) vcld, make_new_child (line: 568)
> |16120|34:34|image| (-3) vcld, main (line: 346)
> 2011-12-27 14:43:37|16120|34:34|image|utils.pm:mail(1255)|SUCCESS -- Sending
> mail To: root@localhost, VCL -- NOTICE DELAY Image Creation base2k3
> 2011-12-27 14:43:37|16120|34:34|image|utils.pm:mail(1255)|SUCCESS -- Sending
> mail To: evq...@fiu.edu, VCL -- NOTICE FAILED Image Creation base2k3
> 2011-12-27
> 14:43:37|16120|34:34|image|utils.pm:update_request_state(1991)|request 34
> state updated to: maintenance, laststate to: image
> 2011-12-27
> 14:43:37|16120|34:34|image|image.pm:reservation_failed(437)|request state
> set to maintenance, laststate to image
> 2011-12-27
> 14:43:37|16120|34:34|image|utils.pm:update_computer_state(2033)|computer 23
> state updated to: maintenance
> 2011-12-27
> 14:43:37|16120|34:34|image|image.pm:reservation_failed(445)|vclimg12 state
> set to maintenance
> 2011-12-27
> 14:43:37|16120|34:34|image|image.pm:reservation_failed(452)|exiting
> 2011-12-27 14:43:37|16120|34:34|image|State.pm:DESTROY(829)|VCL::image
> destructor called, address: 25f4da0
> 2011-12-27
> 14:43:37|16120|34:34|image|utils.pm:delete_computerloadlog_reservation(6742)|removing
> computerloadlog entries matching loadstate = begin
> 2011-12-27
> 14:43:37|16120|34:34|image|utils.pm:delete_computerloadlog_reservation(6789)|deleted
> rows from computerloadlog for reservation id=34
> 2011-12-27 14:43:37|16120|34:34|image|State.pm:DESTROY(848)|number of
> database handles state process created: 3
> 2011-12-27 14:43:37|16120|34:34|image|State.pm:DESTROY(876)|VCL::image
> process duration: 1911 seconds
> 2011-12-27 14:43:37|16120|34:34|image|VIM_SSH.pm:DESTROY(1685)|vim-cmd call
> count: 6
> 2011-12-27 14:43:37|13511|vcld:REAPER(718)|VCL process exited for
> reservation 34, PID: 16120, signal: CHLD
>
