Kiran, A message like this indicates that the virtual machine was unable to start due to some error condition. You need to logon to your VMWare host server vmhost1, and start the vmware console so you can see the message of what input it's asking for. This will give you a clue as to what is wrong.
Mike Waldron Systems Specialist ITS Research Computing University of North Carolina at Chapel Hill CB #3420, ITS Manning, Rm 2509 919-962-9778 -----Original Message----- From: Kiran N [mailto:kiran.nellima...@gmail.com] Sent: Thursday, July 15, 2010 2:39 PM To: vcl-dev@incubator.apache.org Subject: Newly created image reload failing on sandbox Hi All, I made an imaging reservation on the sandbox image and the image got created but that new image cant be reloaded on any computer. I am getting an error. VMControl error -16: Virtual machine requires user input to continue I am not sure as to what input I need to provide and I tried few means for login to the virtual machine but i think I have no access. I just read online that restarting the virtiual machine might help.. Any ideas..? Below is the detailed log when I try to make a reservation on the newly created image. 2010-07-15 13:56:56|15613|vcld:main(165)|lastcheckin time updated for management node 1: 2010-07-15 13:56:56 =========================================================== OUTPUT for vcld run on 2010-07-15 13:57:02 =========================================================== 2010-07-15 13:57:02|27874|vcld:main(116)|vcld environment variable set to 1 for this process 2010-07-15 13:57:02|27874|utils.pm:rename_vcld_process(7901)|renamed process to 'vcld vcld' 2010-07-15 13:57:02|27874|utils.pm:get_management_node_info(6815)|management node info retrieved from database for localhost 2010-07-15 13:57:02|27874|vcld:main(127)|retrieved management node information from database 2010-07-15 13:57:02|27874|vcld:main(140)|management_node_id environment variable set: 1 2010-07-15 13:57:02|27874|vcld:main(148)|management node checkin interval is 5 seconds 2010-07-15 13:57:02|27874|vcld:main(149)|vcld started on localhost 2010-07-15 13:57:07|27874|vcld:main(165)|lastcheckin time updated for management node 1: 2010-07-15 13:57:07 2010-07-15 13:57:12|27874|vcld:main(165)|lastcheckin time updated for management node 1: 2010-07-15 13:57:12 2010-07-15 13:57:18|27874|vcld:main(165)|lastcheckin time updated for management node 1: 2010-07-15 13:57:17 2010-07-15 13:57:18|27874|6:6|new|utils.pm:reservation_being_processed(9634)|computerloadlog 'begin' entry does NOT exist for reservation 6 2010-07-15 13:57:18|27874|6:6|new|utils.pm:reservation_being_processed(9686)|reservation is NOT currently being processed 2010-07-15 13:57:18|27874|6:6|new|vcld:main(276)|reservation 6 is NOT already being processed 2010-07-15 13:57:18|27874|6:6|new|utils.pm:get_request_info(5354)|standalone affiliation found: Local 2010-07-15 13:57:18|27874|6:6|new|utils.pm:get_management_node_info(6815)|management node info retrieved from database for localhost 2010-07-15 13:57:18|27874|6:6|new|vcld:main(281)|retrieved request information from database 2010-07-15 13:57:18|27874|6:6|new|utils.pm:get_management_node_info(6815)|management node info retrieved from database for localhost 2010-07-15 13:57:18|27874|6:6|new|DataStructure.pm:is_parent_reservation(854)|returning true: parent reservation ID for this request: 6 2010-07-15 13:57:18|27874|6:6|new|utils.pm:update_request_state(2186)|request 6 state updated to: pending, laststate to: new 2010-07-15 13:57:18|27874|6:6|new|utils.pm:insertloadlog(4710)|inserted computer=2, begin, beginning to process, state is new 2010-07-15 13:57:18|27874|6:6|new|vcld:make_new_child(509)|loaded VCL::new module 2010-07-15 13:57:18|27904|6:6|new|vcld:make_new_child(582)|vcld environment variable set to 0 for this process 2010-07-15 13:57:18|27904|6:6|new|Module.pm:new(132)|constructor called, class=VCL::new 2010-07-15 13:57:18|27904|6:6|new|Module.pm:new(154)|VCL::new object created 2010-07-15 13:57:18|27874|6:6|new|vcld:make_new_child(566)|current number of forked kids: 1 2010-07-15 13:57:18|27904|6:6|new|State.pm:initialize(85)|obtained a database handle for this state process, stored as $ENV{dbh} 2010-07-15 13:57:18|27904|6:6|new|State.pm:check_image_os(820)|no corrections need to be made, not an imaging request, returning 1 2010-07-15 13:57:18|27904|6:6|new|DataStructure.pm:is_parent_reservation(854)|returning true: parent reservation ID for this request: 6 2010-07-15 13:57:18|27904|6:6|new|utils.pm:rename_vcld_process(7863)|reservation count: 1 2010-07-15 13:57:18|27904|6:6|new|utils.pm:rename_vcld_process(7882)|PARENTIMAGE: 1 2010-07-15 13:57:18|27904|6:6|new|utils.pm:rename_vcld_process(7883)|SUBIMAGE: 0 2010-07-15 13:57:18|27904|6:6|new|utils.pm:rename_vcld_process(7901)|renamed process to 'vcld VCL::new 6:6 new' 2010-07-15 13:57:18|27904|6:6|new|DataStructure.pm:is_parent_reservation(854)|returning true: parent reservation ID for this request: 6 2010-07-15 13:57:18|27904|6:6|new|DataStructure.pm:is_parent_reservation(854)|returning true: parent reservation ID for this request: 6 2010-07-15 13:57:18|27904|6:6|new|State.pm:initialize(121)|attempting to load provisioning module: VCL::Module::Provisioning::vmware 2010-07-15 13:57:18|27904|6:6|new|State.pm:initialize(127)|VCL::Module::Provisioning::vmware module loaded 2010-07-15 13:57:18|27904|6:6|new|Module.pm:new(132)|constructor called, class=VCL::Module::Provisioning::vmware 2010-07-15 13:57:18|27904|6:6|new|Module.pm:new(154)|VCL::Module::Provisioning::vmware object created 2010-07-15 13:57:18|27904|6:6|new|vmware.pm:initialize(105)|vmware module initialized 2010-07-15 13:57:18|27904|6:6|new|State.pm:initialize(131)|VCL::Module::Provisioning::vmware provisioner object created 2010-07-15 13:57:18|27904|6:6|new|State.pm:initialize(145)|attempting to load OS module: VCL::Module::OS::Linux 2010-07-15 13:57:18|27904|6:6|new|State.pm:initialize(151)|VCL::Module::OS::Linux module loaded 2010-07-15 13:57:18|27904|6:6|new|Module.pm:new(132)|constructor called, class=VCL::Module::OS::Linux 2010-07-15 13:57:18|27904|6:6|new|Module.pm:new(154)|VCL::Module::OS::Linux object created 2010-07-15 13:57:18|27904|6:6|new|State.pm:initialize(154)|VCL::Module::OS::Linux OS object created 2010-07-15 13:57:18|27904|6:6|new|State.pm:initialize(169)|returning 1 2010-07-15 13:57:18|27904|6:6|new|vcld:make_new_child(591)|VCL::new object created and initialized 2010-07-15 13:57:18|27904|6:6|new|DataStructure.pm:is_parent_reservation(854)|returning true: parent reservation ID for this request: 6 2010-07-15 13:57:18|27904|6:6|new|DataStructure.pm:get_computer_state_name(1946)|attempting to retrieve current state of computer vm1 from the database 2010-07-15 13:57:18|27904|6:6|new|DataStructure.pm:get_computer_state_name(1977)|retrieved current state of computer vm1 from the database: available 2010-07-15 13:57:18|27904|6:6|new|DataStructure.pm:_automethod(697)|data structure updated: $self->request_data->{reservation}{6}{computer}{state}{name} |27904|6:6|new| computer_state_name = available 2010-07-15 13:57:18|27904|6:6|new|utils.pm:get_management_node_id(9364)|environment variable: 1 2010-07-15 13:57:18|27904|6:6|new|new.pm:process(134)|reservation is parent = 1 2010-07-15 13:57:18|27904|6:6|new|new.pm:process(135)|preload only = 0 2010-07-15 13:57:18|27904|6:6|new|new.pm:process(136)|originating request state = new 2010-07-15 13:57:18|27904|6:6|new|new.pm:process(137)|originating request laststate = new 2010-07-15 13:57:18|27904|6:6|new|new.pm:process(138)|originating computer state = available 2010-07-15 13:57:18|27904|6:6|new|new.pm:process(139)|originating computer type = virtualmachine 2010-07-15 13:57:18|27904|6:6|new|DataStructure.pm:is_parent_reservation(854)|returning true: parent reservation ID for this request: 6 2010-07-15 13:57:18|27904|6:6|new|DataStructure.pm:get_computer_state_name(1946)|attempting to retrieve current state of computer vm1 from the database 2010-07-15 13:57:18|27904|6:6|new|DataStructure.pm:get_computer_state_name(1977)|retrieved current state of computer vm1 from the database: available 2010-07-15 13:57:18|27904|6:6|new|DataStructure.pm:_automethod(697)|data structure updated: $self->request_data->{reservation}{6}{computer}{state}{name} |27904|6:6|new| computer_state_name = available 2010-07-15 13:57:18|27904|6:6|new|utils.pm:get_management_node_id(9364)|environment variable: 1 2010-07-15 13:57:18|27904|6:6|new|new.pm:computer_not_being_used(788)|vm1 state is available 2010-07-15 13:57:18|27904|6:6|new|new.pm:computer_not_being_used(798)|vm1 is available, its state is available 2010-07-15 13:57:18|27904|6:6|new|new.pm:process(170)|vm1 is not being used 2010-07-15 13:57:18|27904|6:6|new|DataStructure.pm:is_parent_reservation(854)|returning true: parent reservation ID for this request: 6 2010-07-15 13:57:18|27904|6:6|new|DataStructure.pm:get_computer_state_name(1946)|attempting to retrieve current state of computer vm1 from the database 2010-07-15 13:57:18|27904|6:6|new|DataStructure.pm:get_computer_state_name(1977)|retrieved current state of computer vm1 from the database: available 2010-07-15 13:57:18|27904|6:6|new|DataStructure.pm:_automethod(697)|data structure updated: $self->request_data->{reservation}{6}{computer}{state}{name} |27904|6:6|new| computer_state_name = available 2010-07-15 13:57:18|27904|6:6|new|utils.pm:get_management_node_id(9364)|environment variable: 1 2010-07-15 13:57:18|27904|6:6|new|new.pm:reload_image(514)|calling VCL::Module::Provisioning::vmware->node_status() 2010-07-15 13:57:18|27904|6:6|new|utils.pm:insertloadlog(4710)|inserted computer=2, statuscheck, checking status of node 2010-07-15 13:57:18|27904|6:6|new|vmware.pm:node_status(1927)|identity_keys= /etc/vcl/vclsandbox_rsa,/etc/vcl/bladelinuxkey_id_rsa 2010-07-15 13:57:18|27904|6:6|new|vmware.pm:node_status(1928)|requestedimagename= vmwarelinux-test12-v0 2010-07-15 13:57:18|27904|6:6|new|vmware.pm:node_status(1929)|image_os_type= linux 2010-07-15 13:57:18|27904|6:6|new|vmware.pm:node_status(1930)|request_forimaging= 0 2010-07-15 13:57:18|27904|6:6|new|vmware.pm:node_status(1931)|vmpath= /var/lib/vmware/runningvms 2010-07-15 13:57:18|27904|6:6|new|vmware.pm:node_status(1932)|datastorepath= /var/lib/vmware/images 2010-07-15 13:57:18|27904|6:6|new|vmware.pm:node_status(1950)|checking if vm1 is pingable 2010-07-15 13:57:18|27904|6:6|new|vmware.pm:node_status(1953)|vm1 is pingable (1) 2010-07-15 13:57:18|27904|6:6|new|utils.pm:run_ssh_command(6180)|executing SSH command on vmhost1: |27904|6:6|new| /usr/bin/ssh -i /etc/vcl/vclsandbox_rsa -i /etc/vcl/bladelinuxkey_id_rsa -l root -p 22 -x vmhost1 'vmware-cmd /var/lib/vmware/runningvms/vmwarelinux-test12-v0vm1/vmwarelinux-test12-v0vm1.vmx getstate' 2>&1 2010-07-15 13:57:18|27904|6:6|new|utils.pm:run_ssh_command(6262)|run_ssh_command output: |27904|6:6|new| /usr/bin/vmware-cmd: Could not connect to VM /var/lib/vmware/runningvms/vmwarelinux-test12-v0vm1/vmwarelinux-test12-v0vm1.vmx |27904|6:6|new| (VMControl error -11: No such virtual machine: The config file /var/lib/vmware/runningvms/vmwarelinux-test12-v0vm1/vmwarelinux-test12-v0vm1.vmx is not registered. |27904|6:6|new| Please register the config file on the server. For example: |27904|6:6|new| vmware-cmd -s register "/var/lib/vmware/runningvms/vmwarelinux-test12-v0vm1/vmwarelinux-test12-v0vm1.vmx") 2010-07-15 13:57:18|27904|6:6|new|utils.pm:run_ssh_command(6272)|SSH command executed on vmhost1, command: |27904|6:6|new| /usr/bin/ssh -i /etc/vcl/vclsandbox_rsa -i /etc/vcl/bladelinuxkey_id_rsa -l root -p 22 -x vmhost1 'vmware-cmd /var/lib/vmware/runningvms/vmwarelinux-test12-v0vm1/vmwarelinux-test12-v0vm1.vmx getstate' 2>&1 |27904|6:6|new| returning (11, "/usr/bin/vmware-cmd: Could not...") 2010-07-15 13:57:18|27904|6:6|new|vmware.pm:node_status(1969)|/usr/bin/vmware-cmd: Could not connect to VM /var/lib/vmware/runningvms/vmwarelinux-test12-v0vm1/vmwarelinux-test12-v0vm1.vmx 2010-07-15 13:57:18|27904|6:6|new|vmware.pm:node_status(1969)|(VMControl error -11: No such virtual machine: The config file /var/lib/vmware/runningvms/vmwarelinux-test12-v0vm1/vmwarelinux-test12-v0vm1.vmx is not registered. 2010-07-15 13:57:18|27904|6:6|new|vmware.pm:node_status(1969)|Please register the config file on the server. For example: 2010-07-15 13:57:18|27904|6:6|new|vmware.pm:node_status(1969)|vmware-cmd -s register "/var/lib/vmware/runningvms/vmwarelinux-test12-v0vm1/vmwarelinux-test12-v0vm1.vmx") 2010-07-15 13:57:18|27904|6:6|new|vmware.pm:node_status(1980)|vm1 vmstate reports 0 2010-07-15 13:57:18|27904|6:6|new|utils.pm:run_ssh_command(6180)|executing SSH command on vm1: |27904|6:6|new| /usr/bin/ssh -i /etc/vcl/vclsandbox_rsa -l root -p 22 -x vm1 'uname -s' 2>&1 2010-07-15 13:57:19|27904|6:6|new|utils.pm:run_ssh_command(6262)|run_ssh_command output: |27904|6:6|new| Linux 2010-07-15 13:57:19|27904|6:6|new|utils.pm:run_ssh_command(6276)|SSH command executed on vm1, returning (0, "Linux") 2010-07-15 13:57:19|27904|6:6|new|utils.pm:run_ssh_command(6180)|executing SSH command on vm1: |27904|6:6|new| /usr/bin/ssh -i /etc/vcl/vclsandbox_rsa -l root -p 22 -x vm1 'cat currentimage.txt' 2>&1 2010-07-15 13:57:19|27904|6:6|new|utils.pm:run_ssh_command(6262)|run_ssh_command output: |27904|6:6|new| vmwarelinux-centosbase10-v2 |27904|6:6|new| id=10 |27904|6:6|new| prettyname=CentOS 5.4 Base Image (VMWare) |27904|6:6|new| imagerevision_id=12 |27904|6:6|new| imagerevision_datecreated=2010-06-07 16:19:25 |27904|6:6|new| computer_id=2 |27904|6:6|new| computer_hostname=vm1 2010-07-15 13:57:19|27904|6:6|new|utils.pm:run_ssh_command(6276)|SSH command executed on vm1, returning (0, "vmwarelinux-centosbase10-v2 id...") 2010-07-15 13:57:19|27904|6:6|new|utils.pm:_getcurrentimage(2679)|stripped dos newline vmwarelinux-centosbase10-v2 2010-07-15 13:57:19|27904|6:6|new|vmware.pm:node_status(1999)|vm1 reports current image is currentimage= vmwarelinux-centosbase10-v2 requestedimagename= vmwarelinux-test12-v0 2010-07-15 13:57:19|27904|6:6|new|vmware.pm:node_status(2018)|returning node status hash reference ($node_status->{status}=RELOAD) 2010-07-15 13:57:19|27904|6:6|new|new.pm:reload_image(529)|node_status returned a hash reference 2010-07-15 13:57:19|27904|6:6|new|new.pm:reload_image(534)|node_status hash reference contains key {status}=RELOAD 2010-07-15 13:57:19|27904|6:6|new|new.pm:reload_image(602)|node status is RELOAD, vm1 will be reloaded 2010-07-15 13:57:19|27904|6:6|new|utils.pm:insertloadlog(4710)|inserted computer=2, loadimageblade, vm1 must be reloaded with vmwarelinux-test12-v0 2010-07-15 13:57:19|27904|6:6|new|new.pm:reload_image(616)|calling VCL::Module::Provisioning::vmware->does_image_exist() 2010-07-15 13:57:19|27904|6:6|new|vmware.pm:does_image_exist(2057)|image repository path: /install/vmware_images 2010-07-15 13:57:19|27904|6:6|new|utils.pm:run_command(9737)|executed command: du -c /install/vmware_images/*vmwarelinux-test12-v0* 2>&1 | grep total 2>&1, pid: 27914, exit status: 0, output: |27904|6:6|new| 2446860 total 2010-07-15 13:57:19|27904|6:6|new|vmware.pm:does_image_exist(2109)|vmwarelinux-test12-v0 exists in /install/vmware_images, size: 2389 MB 2010-07-15 13:57:19|27904|6:6|new|new.pm:reload_image(619)|vmwarelinux-test12-v0 exists on this management node 2010-07-15 13:57:19|27904|6:6|new|utils.pm:insertloadlog(4710)|inserted computer=2, doesimageexists, confirmed image exists 2010-07-15 13:57:19|27904|6:6|new|utils.pm:update_computer_state(2228)|computer 2 state updated to: reloading 2010-07-15 13:57:19|27904|6:6|new|new.pm:reload_image(652)|computer vm1 state set to reloading 2010-07-15 13:57:19|27904|6:6|new|utils.pm:insertloadlog(4710)|inserted computer=2, info, computer state updated to reloading 2010-07-15 13:57:19|27904|6:6|new|new.pm:reload_image(663)|calling VCL::Module::Provisioning::vmware->load() subroutine 2010-07-15 13:57:19|27904|6:6|new|utils.pm:insertloadlog(4710)|inserted computer=2, info, calling VCL::Module::Provisioning::vmware->load() subroutine 2010-07-15 13:57:19|27904|6:6|new|vmware.pm:control_VM(1565)|control remove is defined 2010-07-15 13:57:19|27904|6:6|new|vmware.pm:control_VM(1629)|checking for base image on vmhost1 /var/lib/vmware/images 2010-07-15 13:57:19|27904|6:6|new|utils.pm:run_ssh_command(6180)|executing SSH command on vmhost1: |27904|6:6|new| /usr/bin/ssh -i /etc/vcl/vclsandbox_rsa -l root -p 22 -x vmhost1 'ls -1 /var/lib/vmware/images' 2>&1 2010-07-15 13:57:19|27904|6:6|new|utils.pm:run_ssh_command(6262)|run_ssh_command output: |27904|6:6|new| vmwarelinux-centosbase10-v2 |27904|6:6|new| vmwarelinux-test12-v0 |27904|6:6|new| vmwarewinxp-Alice_Innov811-v5 2010-07-15 13:57:19|27904|6:6|new|utils.pm:run_ssh_command(6276)|SSH command executed on vmhost1, returning (0, "vmwarelinux-centosbase10-v2 vm...") 2010-07-15 13:57:19|27904|6:6|new|vmware.pm:control_VM(1635)|vmwarelinux-centosbase10-v2 vmwarelinux-test12-v0 vmwarewinxp-Alice_Innov811-v5 2010-07-15 13:57:19|27904|6:6|new|vmware.pm:control_VM(1645)|base image exists 2010-07-15 13:57:19|27904|6:6|new|vmware.pm:control_VM(1657)|/var/lib/vmware/runningvms/vmwarelinux-centosbase10-v2vm1/vmwarelinux-centosbase10-v2vm1.vmx directory structure for vmwarelinux-centosbase10-v2vm1 did not exist 2010-07-15 13:57:19|27904|6:6|new|utils.pm:run_ssh_command(6180)|executing SSH command on vmhost1: |27904|6:6|new| /usr/bin/ssh -i /etc/vcl/vclsandbox_rsa -l root -p 22 -x vmhost1 'vmware-cmd -l' 2>&1 2010-07-15 13:57:20|27904|6:6|new|utils.pm:run_ssh_command(6262)|run_ssh_command output: |27904|6:6|new| /var/lib/vmware/managementnode/vmwarelinux-centosbase1617-v1.vmx |27904|6:6|new| /var/lib/vmware/runningvms/vmwarelinux-centosbase10-v2vm1/vmwarelinux-centosbase10-v2vm1.vmx 2010-07-15 13:57:20|27904|6:6|new|utils.pm:run_ssh_command(6276)|SSH command executed on vmhost1, returning (0, "/var/lib/vmware/managementnode...") 2010-07-15 13:57:20|27904|6:6|new|vmware.pm: control_VM(1675)|/var/lib/vmware/managementnode/vmwarelinux-centosbase1617-v1.vmx 2010-07-15 13:57:20|27904|6:6|new|vmware.pm: control_VM(1675)|/var/lib/vmware/runningvms/vmwarelinux-centosbase10-v2vm1/vmwarelinux-centosbase10-v2vm1.vmx 2010-07-15 13:57:20|27904|6:6|new|vmware.pm:control_VM(1683)|my vmx /var/lib/vmware/runningvms/vmwarelinux-centosbase10-v2vm1/vmwarelinux-centosbase10-v2vm1.vmx 2010-07-15 13:57:20|27904|6:6|new|utils.pm:run_ssh_command(6180)|executing SSH command on vmhost1: |27904|6:6|new| /usr/bin/ssh -i /etc/vcl/vclsandbox_rsa -l root -p 22 -x vmhost1 'vmware-cmd /var/lib/vmware/runningvms/vmwarelinux-centosbase10-v2vm1/vmwarelinux-centosbase10-v2vm1.vmx getstate' 2>&1 2010-07-15 13:57:20|27904|6:6|new|utils.pm:run_ssh_command(6262)|run_ssh_command output: |27904|6:6|new| getstate() = on 2010-07-15 13:57:20|27904|6:6|new|utils.pm:run_ssh_command(6276)|SSH command executed on vmhost1, returning (0, "getstate() = on") 2010-07-15 13:57:20|27904|6:6|new|utils.pm:run_ssh_command(6180)|executing SSH command on vmhost1: |27904|6:6|new| /usr/bin/ssh -i /etc/vcl/vclsandbox_rsa -l root -p 22 -x vmhost1 'vmware-cmd /var/lib/vmware/runningvms/vmwarelinux-centosbase10-v2vm1/vmwarelinux-centosbase10-v2vm1.vmx stop hard' 2>&1 2010-07-15 13:57:21|27904|6:6|new|utils.pm:run_ssh_command(6262)|run_ssh_command output: |27904|6:6|new| stop(hard) = 1 2010-07-15 13:57:21|27904|6:6|new|utils.pm:run_ssh_command(6276)|SSH command executed on vmhost1, returning (0, "stop(hard) = 1") 2010-07-15 13:57:21|27904|6:6|new|vmware.pm:control_VM(1701)|turned off /var/lib/vmware/runningvms/vmwarelinux-centosbase10-v2vm1/vmwarelinux-centosbase10-v2vm1.vmx 2010-07-15 13:57:21|27904|6:6|new|utils.pm:run_ssh_command(6180)|executing SSH command on vmhost1: |27904|6:6|new| /usr/bin/ssh -i /etc/vcl/vclsandbox_rsa -l root -p 22 -x vmhost1 'vmware-cmd -s unregister /var/lib/vmware/runningvms/vmwarelinux-centosbase10-v2vm1/vmwarelinux-centosbase10-v2vm1.vmx ' 2>&1 2010-07-15 13:57:21|27904|6:6|new|utils.pm:run_ssh_command(6262)|run_ssh_command output: |27904|6:6|new| unregister(/var/lib/vmware/runningvms/vmwarelinux-centosbase10-v2vm1/vmwarelinux-centosbase10-v2vm1.vmx) = 1 2010-07-15 13:57:21|27904|6:6|new|utils.pm:run_ssh_command(6276)|SSH command executed on vmhost1, returning (0, "unregister(/var/lib/vmware/run...") 2010-07-15 13:57:21|27904|6:6|new|vmware.pm:control_VM(1741)|vm /var/lib/vmware/runningvms/vmwarelinux-centosbase10-v2vm1/vmwarelinux-centosbase10-v2vm1.vmx unregistered 2010-07-15 13:57:21|27904|6:6|new|utils.pm:run_ssh_command(6180)|executing SSH command on vmhost1: |27904|6:6|new| /usr/bin/ssh -i /etc/vcl/vclsandbox_rsa -l root -p 22 -x vmhost1 '/bin/rm -rf /var/lib/vmware/runningvms/vmwarelinux-centosbase10-v2vm1' 2>&1 2010-07-15 13:57:21|27904|6:6|new|utils.pm:run_ssh_command(6262)|run_ssh_command output: |27904|6:6|new| none 2010-07-15 13:57:22|27904|6:6|new|utils.pm:run_ssh_command(6276)|SSH command executed on vmhost1, returning (0, "none") 2010-07-15 13:57:22|27904|6:6|new|vmware.pm:control_VM(1748)|removed /var/lib/vmware/runningvms/vmwarelinux-centosbase10-v2vm1 from vmhost1 2010-07-15 13:57:22|27904|6:6|new|DataStructure.pm:get_computer_private_ip_address(1418)|returning private IP address previously retrieved from /etc/hosts: 192.168.50.10 2010-07-15 13:57:22|27904|6:6|new|utils.pm:insertloadlog(4710)|inserted computer=2, startload, vm1 vmwarelinux-test12-v0 2010-07-15 13:57:22|27904|6:6|new|vmware.pm:load(216)|identity file set /etc/vcl/vclsandbox_rsa vmhost imagename rh4image-VMwareserverhostRHEL48-v3 bladekey /etc/vcl/vclsandbox_rsa 2010-07-15 13:57:22|27904|6:6|new|vmware.pm:load(244)|persistent= 0 2010-07-15 13:57:22|27904|6:6|new|vmware.pm:load(245)|myvmdir= vmwarelinux-test12-v0vm1 2010-07-15 13:57:22|27904|6:6|new|vmware.pm:load(246)|myvmx= /var/lib/vmware/runningvms/vmwarelinux-test12-v0vm1/vmwarelinux-test12-v0vm1.vmx 2010-07-15 13:57:22|27904|6:6|new|vmware.pm:load(247)|mybasedirname= vmwarelinux-test12-v0 2010-07-15 13:57:22|27904|6:6|new|vmware.pm:load(248)|myimagename= vmwarelinux-test12-v0 2010-07-15 13:57:22|27904|6:6|new|vmware.pm:load(251)|checking for base image vmwarelinux-test12-v0vm1 on vmhost1 2010-07-15 13:57:22|27904|6:6|new|utils.pm:insertloadlog(4710)|inserted computer=2, vmround1, checking host for requested image files 2010-07-15 13:57:22|27904|6:6|new|vmware.pm:load(256)|trying to create exclusive lock on /tmp/vmhost1vmwarelinux-test12-v0lock while checking if image files exist on host 2010-07-15 13:57:22|27904|6:6|new|vmware.pm:load(259)|owning exclusive lock on /tmp/vmhost1vmwarelinux-test12-v0lock 2010-07-15 13:57:22|27904|6:6|new|vmware.pm:load(260)|listing datestore /var/lib/vmware/images 2010-07-15 13:57:22|27904|6:6|new|utils.pm:run_ssh_command(6180)|executing SSH command on vmhost1: |27904|6:6|new| /usr/bin/ssh -i /etc/vcl/vclsandbox_rsa -l root -p 22 -x vmhost1 'ls -1 /var/lib/vmware/images' 2>&1 2010-07-15 13:57:22|27904|6:6|new|utils.pm:run_ssh_command(6262)|run_ssh_command output: |27904|6:6|new| vmwarelinux-centosbase10-v2 |27904|6:6|new| vmwarelinux-test12-v0 |27904|6:6|new| vmwarewinxp-Alice_Innov811-v5 2010-07-15 13:57:22|27904|6:6|new|utils.pm:run_ssh_command(6276)|SSH command executed on vmhost1, returning (0, "vmwarelinux-centosbase10-v2 vm...") 2010-07-15 13:57:22|27904|6:6|new|vmware.pm:load(270)|data store contents /var/lib/vmware/images on vm host: |27904|6:6|new| vmwarelinux-centosbase10-v2 vmwarelinux-test12-v0 vmwarewinxp-Alice_Innov811-v5 2010-07-15 13:57:22|27904|6:6|new|vmware.pm:load(283)|base image exists 2010-07-15 13:57:22|27904|6:6|new|vmware.pm:load(549)|confirm image exist process complete removing lock on /tmp/vmhost1vmwarelinux-test12-v0lock 2010-07-15 13:57:22|27904|6:6|new|vmware.pm:load(611)|created tmp directory /tmp/vmwarelinux-test12-v0vm1 |27904|6:6|new| ---- WARNING ---- |27904|6:6|new| 2010-07-15 13:57:22|27904|6:6|new|vmware.pm:load(635)|image memory value 64 out of the expected range in host machine 8096 setting to 512 |27904|6:6|new| ( 0) utils.pm, notify (line: 737) |27904|6:6|new| (-1) vmware.pm, load (line: 635) |27904|6:6|new| (-2) new.pm, reload_image (line: 665) |27904|6:6|new| (-3) new.pm, process (line: 266) |27904|6:6|new| (-4) vcld, make_new_child (line: 594) |27904|6:6|new| (-5) vcld, main (line: 341) 2010-07-15 13:57:22|27904|6:6|new|vmware.pm:load(646)|sda flag set, setting adapter to buslogic 2010-07-15 13:57:22|27904|6:6|new|vmware.pm:load(658)|path is /install/vmware_images/vmwarelinux-test12-v0/vmwarelinux-test12-v0.vmdk 2010-07-15 13:57:22|27904|6:6|new|vmware.pm:load(668)|grep: /install/vmware_images/vmwarelinux-test12-v0/vmwarelinux-test12-v0.vmdk: No such file or directory 2010-07-15 13:57:22|27904|6:6|new|vmware.pm:load(676)|adapter= buslogic drivetype sda 2010-07-15 13:57:22|27904|6:6|new|vmware.pm:load(753)|wrote vmxarray to /tmp/vmwarelinux-test12-v0vm1/vmwarelinux-test12-v0vm1.vmx 2010-07-15 13:57:22|27904|6:6|new|utils.pm:insertloadlog(4710)|inserted computer=2, vmconfigcopy, transferring vmx file to vmhost1 2010-07-15 13:57:22|27904|6:6|new|utils.pm:run_scp_command(6403)|attempt 1/3: executing SCP command: /usr/bin/scp -B -i /etc/vcl/vclsandbox_rsa -P 22 -p -r /tmp/vmwarelinux-test12-v0vm1 vmhost1:"/var/lib/vmware/runningvms" 2>&1 2010-07-15 13:57:22|27904|6:6|new|utils.pm:run_scp_command(6453)|scp successful: attempt 1/3, exit status: 0, output: none 2010-07-15 13:57:22|27904|6:6|new|utils.pm:run_ssh_command(6180)|executing SSH command on vmhost1: |27904|6:6|new| /usr/bin/ssh -i /etc/vcl/vclsandbox_rsa -l root -p 22 -x vmhost1 'ls -1 /var/lib/vmware/runningvms/vmwarelinux-test12-v0vm1;chmod 755 /var/lib/vmware/runningvms/vmwarelinux-test12-v0vm1/vmwarelinux-test12-v0vm1.vmx' 2>&1 2010-07-15 13:57:22|27904|6:6|new|utils.pm:run_ssh_command(6262)|run_ssh_command output: |27904|6:6|new| vmwarelinux-test12-v0vm1.vmx 2010-07-15 13:57:22|27904|6:6|new|utils.pm:run_ssh_command(6276)|SSH command executed on vmhost1, returning (0, "vmwarelinux-test12-v0vm1.vmx") 2010-07-15 13:57:22|27904|6:6|new|vmware.pm:load(769)|successfully copied vmx file to vmhost1 2010-07-15 13:57:22|27904|6:6|new|utils.pm:insertloadlog(4710)|inserted computer=2, vmsetupconfig, setting up vmx file 2010-07-15 13:57:22|27904|6:6|new|vmware.pm:load(790)|successfully removed /tmp/vmwarelinux-test12-v0vm1/vmwarelinux-test12-v0vm1.vmx 2010-07-15 13:57:22|27904|6:6|new|vmware.pm:load(791)|successfully removed tmp directory 2010-07-15 13:57:22|27904|6:6|new|utils.pm:run_ssh_command(6180)|executing SSH command on vmhost1: |27904|6:6|new| /usr/bin/ssh -i /etc/vcl/vclsandbox_rsa -l root -p 22 -x vmhost1 'vmware-cmd -s register /var/lib/vmware/runningvms/vmwarelinux-test12-v0vm1/vmwarelinux-test12-v0vm1.vmx' 2>&1 2010-07-15 13:57:23|27904|6:6|new|utils.pm:run_ssh_command(6262)|run_ssh_command output: |27904|6:6|new| register(/var/lib/vmware/runningvms/vmwarelinux-test12-v0vm1/vmwarelinux-test12-v0vm1.vmx) = 1 2010-07-15 13:57:23|27904|6:6|new|utils.pm:run_ssh_command(6276)|SSH command executed on vmhost1, returning (0, "register(/var/lib/vmware/runni...") 2010-07-15 13:57:23|27904|6:6|new|vmware.pm:load(805)|vm /var/lib/vmware/runningvms/vmwarelinux-test12-v0vm1/vmwarelinux-test12-v0vm1.vmx registered 2010-07-15 13:57:23|27904|6:6|new|vmware.pm:load(827)|starting vm /var/lib/vmware/runningvms/vmwarelinux-test12-v0vm1/vmwarelinux-test12-v0vm1.vmx - pass 1 2010-07-15 13:57:23|27904|6:6|new|utils.pm:run_ssh_command(6180)|executing SSH command on vmhost1: |27904|6:6|new| /usr/bin/ssh -i /etc/vcl/vclsandbox_rsa -l root -p 22 -x vmhost1 'vmware-cmd /var/lib/vmware/runningvms/vmwarelinux-test12-v0vm1/vmwarelinux-test12-v0vm1.vmx start' 2>&1 2010-07-15 13:57:23|27874|vcld:main(165)|lastcheckin time updated for management node 1: 2010-07-15 13:57:23 2010-07-15 13:57:23|27904|6:6|new|utils.pm:run_ssh_command(6262)|run_ssh_command output: |27904|6:6|new| VMControl error -16: Virtual machine requires user input to continue 2010-07-15 13:57:23|27904|6:6|new|utils.pm:run_ssh_command(6272)|SSH command executed on vmhost1, command: |27904|6:6|new| /usr/bin/ssh -i /etc/vcl/vclsandbox_rsa -l root -p 22 -x vmhost1 'vmware-cmd /var/lib/vmware/runningvms/vmwarelinux-test12-v0vm1/vmwarelinux-test12-v0vm1.vmx start' 2>&1 |27904|6:6|new| returning (16, "VMControl error -16: Virtual m...") 2010-07-15 13:57:23|27904|6:6|new|vmware.pm:load(843)|vmware-cmd start failed |27904|6:6|new| VMControl error -16: Virtual machine requires user input to continue |27904|6:6|new| ---- WARNING ---- |27904|6:6|new| 2010-07-15 13:57:23|27904|6:6|new|new.pm:reload_image(670)|vmwarelinux-test12-v0 failed to load on vm1, returning |27904|6:6|new| ( 0) utils.pm, notify (line: 737) |27904|6:6|new| (-1) new.pm, reload_image (line: 670) |27904|6:6|new| (-2) new.pm, process (line: 266) |27904|6:6|new| (-3) vcld, make_new_child (line: 594) |27904|6:6|new| (-4) vcld, main (line: 341) 2010-07-15 13:57:23|27904|6:6|new|utils.pm:insertloadlog(4710)|inserted computer=2, loadimagefailed, vmwarelinux-test12-v0 failed to load on vm1 |27904|6:6|new| ---- WARNING ---- |27904|6:6|new| 2010-07-15 13:57:23|27904|6:6|new|new.pm:process(313)|failed to load vm1 with vmwarelinux-test12-v0 |27904|6:6|new| ( 0) utils.pm, notify (line: 737) |27904|6:6|new| (-1) new.pm, process (line: 313) |27904|6:6|new| (-2) vcld, make_new_child (line: 594) |27904|6:6|new| (-3) vcld, main (line: 341) 2010-07-15 13:57:23|27904|6:6|new|DataStructure.pm:get_computer_state_name(1946)|attempting to retrieve current state of computer vm1 from the database 2010-07-15 13:57:23|27904|6:6|new|DataStructure.pm:get_computer_state_name(1977)|retrieved current state of computer vm1 from the database: reloading 2010-07-15 13:57:23|27904|6:6|new|DataStructure.pm:_automethod(697)|data structure updated: $self->request_data->{reservation}{6}{computer}{state}{name} |27904|6:6|new| computer_state_name = reloading No recipient addresses found in header 2010-07-15 13:57:23|27904|6:6|new|utils.pm:mail(1348)|SUCCESS -- Sending mail To: , PROBLEM -- State.pm |27904|6:6|new| ---- CRITICAL ---- |27904|6:6|new| 2010-07-15 13:57:23|27904|6:6|new|State.pm:reservation_failed(290)|reservation failed on vm1: process failed after trying to load or make available |27904|6:6|new| ( 0) utils.pm, notify (line: 737) |27904|6:6|new| (-1) State.pm, reservation_failed (line: 290) |27904|6:6|new| (-2) new.pm, process (line: 316) |27904|6:6|new| (-3) vcld, make_new_child (line: 594) |27904|6:6|new| (-4) vcld, main (line: 341) 2010-07-15 13:57:23|27904|6:6|new|utils.pm:insertloadlog(4710)|inserted computer=2, failed, process failed after trying to load or make available 2010-07-15 13:57:23|27904|6:6|new|State.pm:reservation_failed(293)|inserted computerloadlog entry 2010-07-15 13:57:23|27904|6:6|new|State.pm:reservation_failed(301)|updated log ending value to 'failed', logid=3 2010-07-15 13:57:23|27904|6:6|new|utils.pm:update_computer_state(2228)|computer 2 state updated to: failed 2010-07-15 13:57:23|27904|6:6|new|State.pm:reservation_failed(312)|computer vm1 (2) state set to failed 2010-07-15 13:57:23|27904|6:6|new|utils.pm:update_request_state(2186)|request 6 state updated to: failed, laststate to: new 2010-07-15 13:57:23|27904|6:6|new|State.pm:reservation_failed(325)|set request state to 'failed'/'new' 2010-07-15 13:57:23|27904|6:6|new|utils.pm:is_inblockrequest(6972)|zero rows were returned from database select 2010-07-15 13:57:23|27904|6:6|new|State.pm:reservation_failed(343)|vm1 is NOT in blockcomputers table 2010-07-15 13:57:23|27904|6:6|new|State.pm:reservation_failed(346)|exiting 1 2010-07-15 13:57:23|27904|6:6|new|State.pm:DESTROY(905)|destructor called, ref($self)=VCL::new 2010-07-15 13:57:23|27904|6:6|new|utils.pm:delete_computerloadlog_reservation(7551)|removing computerloadlog entries matching loadstate = begin 2010-07-15 13:57:23|27904|6:6|new|utils.pm:delete_computerloadlog_reservation(7598)|deleted rows from computerloadlog for reservation id=6 2010-07-15 13:57:23|27904|6:6|new|State.pm:DESTROY(912)|removed computerloadlog rows with loadstate=begin for reservation 2010-07-15 13:57:23|27904|6:6|new|State.pm:DESTROY(924)|number of database handles state process created: 1 2010-07-15 13:57:23|27904|6:6|new|State.pm:DESTROY(933)|process has a database handle stored in $ENV{dbh}, attempting disconnect 2010-07-15 13:57:23|27904|6:6|new|State.pm:DESTROY(935)|$ENV{dbh}: database disconnect successful 2010-07-15 13:57:23|27904|6:6|new|State.pm:DESTROY(949)|VCL::new process 27904 exiting 2010-07-15 13:57:23|27874|vcld:REAPER(744)|VCL process exited for reservation 6 -- Thanks, Kiran
