Making a bit of progress... Hit another snag. After the image is copied, it
tries to start it up but hits an error because the VM requires user input:
|32571|10:10|new| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
localvmhost 'vmware-cmd
/home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx
start' 2>&1
...
|32571|10:10|new| VMControl error -16: Virtual machine requires user input
to continue
Starting the VM up in the vmware GUI client gives the error "Cannot open the
disk
'/images/vmware/vmwarelinux-xubuntu904-v0/vmwarelinux-xubuntu904-v0.vmdk' or
one of the snapshot disks it depends on. Reason: Failed to lock the file.".
The disk image exists:
$ ls -l
/images/vmware/vmwarelinux-xubuntu904-v0/vmwarelinux-xubuntu904-v0.vmdk
2524548 -rw------- 1 root root 2524544 Apr 28 09:53
/images/vmware/vmwarelinux-xubuntu904-v0/vmwarelinux-xubuntu904-v0.vmdk
As far as I can tell, there are no locks on the disk anyware.
I am enclosing the vcld.log.
Thanks in advance,
Mark
--
Mark Gardner
--
===========================================================
OUTPUT for vcld run on 2010-04-28 09:53:22
===========================================================
2010-04-28 09:53:22|32550|vcld:main(116)|vcld environment variable set to 1 for this process
2010-04-28 09:53:22|32550|utils.pm:rename_vcld_process(7901)|renamed process to 'vcld vcld'
2010-04-28 09:53:22|32550|utils.pm:get_management_node_info(6815)|management node info retrieved from database for localhost
2010-04-28 09:53:22|32550|vcld:main(127)|retrieved management node information from database
2010-04-28 09:53:22|32550|vcld:main(140)|management_node_id environment variable set: 1
2010-04-28 09:53:22|32550|vcld:main(148)|management node checkin interval is 5 seconds
2010-04-28 09:53:22|32550|vcld:main(149)|vcld started on localhost
2010-04-28 09:53:27|32550|vcld:main(165)|lastcheckin time updated for management node 1: 2010-04-28 09:53:27
...
2010-04-28 09:53:42|32550|vcld:main(165)|lastcheckin time updated for management node 1: 2010-04-28 09:53:42
2010-04-28 09:53:42|32550|10:10|new|utils.pm:reservation_being_processed(9634)|computerloadlog 'begin' entry does NOT exist for reservation 10
2010-04-28 09:53:42|32550|10:10|new|utils.pm:reservation_being_processed(9686)|reservation is NOT currently being processed
2010-04-28 09:53:42|32550|10:10|new|vcld:main(276)|reservation 10 is NOT already being processed
2010-04-28 09:53:42|32550|10:10|new|utils.pm:get_request_info(5354)|standalone affiliation found: Local
2010-04-28 09:53:42|32550|10:10|new|utils.pm:get_management_node_info(6815)|management node info retrieved from database for localhost
2010-04-28 09:53:42|32550|10:10|new|vcld:main(281)|retrieved request information from database
2010-04-28 09:53:42|32550|10:10|new|utils.pm:get_management_node_info(6815)|management node info retrieved from database for localhost
2010-04-28 09:53:42|32550|10:10|new|DataStructure.pm:is_parent_reservation(854)|returning true: parent reservation ID for this request: 10
2010-04-28 09:53:42|32550|10:10|new|utils.pm:update_request_state(2186)|request 10 state updated to: pending, laststate to: new
2010-04-28 09:53:42|32550|10:10|new|utils.pm:insertloadlog(4710)|inserted computer=2, begin, beginning to process, state is new
2010-04-28 09:53:42|32550|10:10|new|vcld:make_new_child(509)|loaded VCL::new module
2010-04-28 09:53:42|32550|10:10|new|vcld:make_new_child(566)|current number of forked kids: 1
2010-04-28 09:53:42|32571|10:10|new|vcld:make_new_child(582)|vcld environment variable set to 0 for this process
2010-04-28 09:53:42|32571|10:10|new|Module.pm:new(132)|constructor called, class=VCL::new
2010-04-28 09:53:42|32571|10:10|new|Module.pm:new(154)|VCL::new object created
2010-04-28 09:53:42|32571|10:10|new|State.pm:initialize(85)|obtained a database handle for this state process, stored as $ENV{dbh}
2010-04-28 09:53:42|32571|10:10|new|State.pm:check_image_os(820)|no corrections need to be made, not an imaging request, returning 1
2010-04-28 09:53:42|32571|10:10|new|DataStructure.pm:is_parent_reservation(854)|returning true: parent reservation ID for this request: 10
2010-04-28 09:53:42|32571|10:10|new|utils.pm:rename_vcld_process(7863)|reservation count: 1
2010-04-28 09:53:42|32571|10:10|new|utils.pm:rename_vcld_process(7882)|PARENTIMAGE: 1
2010-04-28 09:53:42|32571|10:10|new|utils.pm:rename_vcld_process(7883)|SUBIMAGE: 0
2010-04-28 09:53:42|32571|10:10|new|utils.pm:rename_vcld_process(7901)|renamed process to 'vcld VCL::new 10:10 new'
2010-04-28 09:53:42|32571|10:10|new|DataStructure.pm:is_parent_reservation(854)|returning true: parent reservation ID for this request: 10
2010-04-28 09:53:42|32571|10:10|new|DataStructure.pm:is_parent_reservation(854)|returning true: parent reservation ID for this request: 10
2010-04-28 09:53:42|32571|10:10|new|State.pm:initialize(121)|attempting to load provisioning module: VCL::Module::Provisioning::vmware
2010-04-28 09:53:42|32571|10:10|new|State.pm:initialize(127)|VCL::Module::Provisioning::vmware module loaded
2010-04-28 09:53:42|32571|10:10|new|Module.pm:new(132)|constructor called, class=VCL::Module::Provisioning::vmware
2010-04-28 09:53:42|32571|10:10|new|Module.pm:new(154)|VCL::Module::Provisioning::vmware object created
2010-04-28 09:53:42|32571|10:10|new|vmware.pm:initialize(105)|vmware module initialized
2010-04-28 09:53:42|32571|10:10|new|State.pm:initialize(131)|VCL::Module::Provisioning::vmware provisioner object created
2010-04-28 09:53:42|32571|10:10|new|State.pm:initialize(145)|attempting to load OS module: VCL::Module::OS::Linux
2010-04-28 09:53:42|32571|10:10|new|State.pm:initialize(151)|VCL::Module::OS::Linux module loaded
2010-04-28 09:53:42|32571|10:10|new|Module.pm:new(132)|constructor called, class=VCL::Module::OS::Linux
2010-04-28 09:53:42|32571|10:10|new|Module.pm:new(154)|VCL::Module::OS::Linux object created
2010-04-28 09:53:42|32571|10:10|new|State.pm:initialize(154)|VCL::Module::OS::Linux OS object created
2010-04-28 09:53:42|32571|10:10|new|State.pm:initialize(169)|returning 1
2010-04-28 09:53:42|32571|10:10|new|vcld:make_new_child(591)|VCL::new object created and initialized
2010-04-28 09:53:42|32571|10:10|new|DataStructure.pm:is_parent_reservation(854)|returning true: parent reservation ID for this request: 10
2010-04-28 09:53:42|32571|10:10|new|DataStructure.pm:get_computer_state_name(1946)|attempting to retrieve current state of computer vmguest-1 from the database
2010-04-28 09:53:42|32571|10:10|new|DataStructure.pm:get_computer_state_name(1977)|retrieved current state of computer vmguest-1 from the database: available
2010-04-28 09:53:42|32571|10:10|new|DataStructure.pm:_automethod(697)|data structure updated: $self->request_data->{reservation}{10}{computer}{state}{name}
|32571|10:10|new| computer_state_name = available
2010-04-28 09:53:42|32571|10:10|new|utils.pm:get_management_node_id(9364)|environment variable: 1
2010-04-28 09:53:42|32571|10:10|new|new.pm:process(134)|reservation is parent = 1
2010-04-28 09:53:42|32571|10:10|new|new.pm:process(135)|preload only = 0
2010-04-28 09:53:42|32571|10:10|new|new.pm:process(136)|originating request state = new
2010-04-28 09:53:42|32571|10:10|new|new.pm:process(137)|originating request laststate = new
2010-04-28 09:53:42|32571|10:10|new|new.pm:process(138)|originating computer state = available
2010-04-28 09:53:42|32571|10:10|new|new.pm:process(139)|originating computer type = virtualmachine
2010-04-28 09:53:42|32571|10:10|new|DataStructure.pm:is_parent_reservation(854)|returning true: parent reservation ID for this request: 10
2010-04-28 09:53:42|32571|10:10|new|DataStructure.pm:get_computer_state_name(1946)|attempting to retrieve current state of computer vmguest-1 from the database
2010-04-28 09:53:42|32571|10:10|new|DataStructure.pm:get_computer_state_name(1977)|retrieved current state of computer vmguest-1 from the database: available
2010-04-28 09:53:42|32571|10:10|new|DataStructure.pm:_automethod(697)|data structure updated: $self->request_data->{reservation}{10}{computer}{state}{name}
|32571|10:10|new| computer_state_name = available
2010-04-28 09:53:42|32571|10:10|new|utils.pm:get_management_node_id(9364)|environment variable: 1
2010-04-28 09:53:42|32571|10:10|new|new.pm:computer_not_being_used(788)|vmguest-1 state is available
2010-04-28 09:53:42|32571|10:10|new|new.pm:computer_not_being_used(798)|vmguest-1 is available, its state is available
2010-04-28 09:53:42|32571|10:10|new|new.pm:process(170)|vmguest-1 is not being used
2010-04-28 09:53:42|32571|10:10|new|DataStructure.pm:is_parent_reservation(854)|returning true: parent reservation ID for this request: 10
2010-04-28 09:53:42|32571|10:10|new|DataStructure.pm:get_computer_state_name(1946)|attempting to retrieve current state of computer vmguest-1 from the database
2010-04-28 09:53:42|32571|10:10|new|DataStructure.pm:get_computer_state_name(1977)|retrieved current state of computer vmguest-1 from the database: available
2010-04-28 09:53:42|32571|10:10|new|DataStructure.pm:_automethod(697)|data structure updated: $self->request_data->{reservation}{10}{computer}{state}{name}
|32571|10:10|new| computer_state_name = available
2010-04-28 09:53:42|32571|10:10|new|utils.pm:get_management_node_id(9364)|environment variable: 1
2010-04-28 09:53:42|32571|10:10|new|new.pm:reload_image(514)|calling VCL::Module::Provisioning::vmware->node_status()
2010-04-28 09:53:42|32571|10:10|new|utils.pm:insertloadlog(4710)|inserted computer=2, statuscheck, checking status of node
2010-04-28 09:53:42|32571|10:10|new|vmware.pm:node_status(1888)|identity_keys= /etc/vcl/vcl.key
2010-04-28 09:53:42|32571|10:10|new|vmware.pm:node_status(1889)|requestedimagename= vmwarelinux-xubuntu904-v0
2010-04-28 09:53:42|32571|10:10|new|vmware.pm:node_status(1890)|image_os_type= linux
2010-04-28 09:53:42|32571|10:10|new|vmware.pm:node_status(1891)|request_forimaging= 0
2010-04-28 09:53:42|32571|10:10|new|vmware.pm:node_status(1892)|vmpath= /home/vm/vmware
2010-04-28 09:53:42|32571|10:10|new|vmware.pm:node_status(1893)|datastorepath= /images/vmware
2010-04-28 09:53:42|32571|10:10|new|vmware.pm:node_status(1911)|checking if vmguest-1 is pingable
2010-04-28 09:53:42|32571|10:10|new|vmware.pm:node_status(1914)|vmguest-1 is pingable (1)
2010-04-28 09:53:42|32571|10:10|new|utils.pm:run_ssh_command(6180)|executing SSH command on localvmhost:
|32571|10:10|new| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x localvmhost 'vmware-cmd /home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx getstate' 2>&1
2010-04-28 09:53:42|32571|10:10|new|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|32571|10:10|new| /usr/bin/vmware-cmd: Could not connect to VM /home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx
|32571|10:10|new| (VMControl error -11: No such virtual machine: The config file /home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx is not registered.
|32571|10:10|new| Please register the config file on the server. For example:
|32571|10:10|new| vmware-cmd -s register "/home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx")
2010-04-28 09:53:42|32571|10:10|new|utils.pm:run_ssh_command(6272)|SSH command executed on localvmhost, command:
|32571|10:10|new| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x localvmhost 'vmware-cmd /home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx getstate' 2>&1
|32571|10:10|new| returning (11, "/usr/bin/vmware-cmd: Could not...")
2010-04-28 09:53:42|32571|10:10|new|vmware.pm:node_status(1930)|/usr/bin/vmware-cmd: Could not connect to VM /home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx
2010-04-28 09:53:42|32571|10:10|new|vmware.pm:node_status(1930)|(VMControl error -11: No such virtual machine: The config file /home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx is not registered.
2010-04-28 09:53:42|32571|10:10|new|vmware.pm:node_status(1930)|Please register the config file on the server. For example:
2010-04-28 09:53:42|32571|10:10|new|vmware.pm:node_status(1930)|vmware-cmd -s register "/home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx")
2010-04-28 09:53:42|32571|10:10|new|vmware.pm:node_status(1941)|vmguest-1 vmstate reports 0
2010-04-28 09:53:43|32571|10:10|new|utils.pm:run_ssh_command(6180)|executing SSH command on vmguest-1:
|32571|10:10|new| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x vmguest-1 'uname -s' 2>&1
2010-04-28 09:53:47|32550|vcld:main(165)|lastcheckin time updated for management node 1: 2010-04-28 09:53:47
2010-04-28 09:53:48|32571|10:10|new|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|32571|10:10|new| Linux
2010-04-28 09:53:48|32571|10:10|new|utils.pm:run_ssh_command(6276)|SSH command executed on vmguest-1, returning (0, "Linux")
2010-04-28 09:53:48|32571|10:10|new|utils.pm:run_ssh_command(6180)|executing SSH command on vmguest-1:
|32571|10:10|new| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x vmguest-1 'cat currentimage.txt' 2>&1
2010-04-28 09:53:52|32550|vcld:main(165)|lastcheckin time updated for management node 1: 2010-04-28 09:53:52
2010-04-28 09:53:53|32571|10:10|new|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|32571|10:10|new| cat: currentimage.txt: No such file or directory
2010-04-28 09:53:53|32571|10:10|new|utils.pm:run_ssh_command(6272)|SSH command executed on vmguest-1, command:
|32571|10:10|new| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x vmguest-1 'cat currentimage.txt' 2>&1
|32571|10:10|new| returning (1, "cat: currentimage.txt: No such...")
2010-04-28 09:53:53|32571|10:10|new|vmware.pm:node_status(1979)|returning node status hash reference ($node_status->{status}=RELOAD)
2010-04-28 09:53:53|32571|10:10|new|new.pm:reload_image(529)|node_status returned a hash reference
2010-04-28 09:53:53|32571|10:10|new|new.pm:reload_image(534)|node_status hash reference contains key {status}=RELOAD
2010-04-28 09:53:53|32571|10:10|new|new.pm:reload_image(602)|node status is RELOAD, vmguest-1 will be reloaded
2010-04-28 09:53:53|32571|10:10|new|utils.pm:insertloadlog(4710)|inserted computer=2, loadimageblade, vmguest-1 must be reloaded with vmwarelinux-xubuntu904-v0
2010-04-28 09:53:53|32571|10:10|new|new.pm:reload_image(616)|calling VCL::Module::Provisioning::vmware->does_image_exist()
2010-04-28 09:53:53|32571|10:10|new|vmware.pm:does_image_exist(2018)|image repository path: /home/vm/vmware
2010-04-28 09:53:53|32571|10:10|new|utils.pm:run_command(9737)|executed command: du -c /home/vm/vmware/*vmwarelinux-xubuntu904-v0* 2>&1 | grep total 2>&1, pid: 32588, exit status: 0, output:
|32571|10:10|new| 2987340 total
2010-04-28 09:53:53|32571|10:10|new|vmware.pm:does_image_exist(2070)|vmwarelinux-xubuntu904-v0 exists in /home/vm/vmware, size: 2917 MB
2010-04-28 09:53:53|32571|10:10|new|new.pm:reload_image(619)|vmwarelinux-xubuntu904-v0 exists on this management node
2010-04-28 09:53:53|32571|10:10|new|utils.pm:insertloadlog(4710)|inserted computer=2, doesimageexists, confirmed image exists
2010-04-28 09:53:53|32571|10:10|new|utils.pm:update_computer_state(2228)|computer 2 state updated to: reloading
2010-04-28 09:53:53|32571|10:10|new|new.pm:reload_image(652)|computer vmguest-1 state set to reloading
2010-04-28 09:53:53|32571|10:10|new|utils.pm:insertloadlog(4710)|inserted computer=2, info, computer state updated to reloading
2010-04-28 09:53:53|32571|10:10|new|new.pm:reload_image(663)|calling VCL::Module::Provisioning::vmware->load() subroutine
2010-04-28 09:53:53|32571|10:10|new|utils.pm:insertloadlog(4710)|inserted computer=2, info, calling VCL::Module::Provisioning::vmware->load() subroutine
2010-04-28 09:53:53|32571|10:10|new|vmware.pm:control_VM(1526)|control remove is defined
2010-04-28 09:53:53|32571|10:10|new|vmware.pm:control_VM(1590)|checking for base image on localvmhost /images/vmware
2010-04-28 09:53:53|32571|10:10|new|utils.pm:run_ssh_command(6180)|executing SSH command on localvmhost:
|32571|10:10|new| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x localvmhost 'ls -1 /images/vmware' 2>&1
2010-04-28 09:53:53|32571|10:10|new|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|32571|10:10|new| none
2010-04-28 09:53:53|32571|10:10|new|utils.pm:run_ssh_command(6276)|SSH command executed on localvmhost, returning (0, "none")
2010-04-28 09:53:53|32571|10:10|new|vmware.pm:control_VM(1596)|none
2010-04-28 09:53:53|32571|10:10|new|vmware.pm:control_VM(1618)|/home/vm/vmware/noimagevmguest-1/noimagevmguest-1.vmx directory structure for noimagevmguest-1 did not exist
2010-04-28 09:53:53|32571|10:10|new|utils.pm:run_ssh_command(6180)|executing SSH command on localvmhost:
|32571|10:10|new| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x localvmhost 'vmware-cmd -l' 2>&1
2010-04-28 09:53:53|32571|10:10|new|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|32571|10:10|new| /home/vm/vmware/vmwarelinux-xubuntu904-v0/vmwarelinux-xubuntu904-v0.vmx
2010-04-28 09:53:53|32571|10:10|new|utils.pm:run_ssh_command(6276)|SSH command executed on localvmhost, returning (0, "/home/vm/vmware/vmwarelinux-xu...")
2010-04-28 09:53:53|32571|10:10|new|vmware.pm:control_VM(1636)|/home/vm/vmware/vmwarelinux-xubuntu904-v0/vmwarelinux-xubuntu904-v0.vmx
2010-04-28 09:53:53|32571|10:10|new|utils.pm:run_ssh_command(6180)|executing SSH command on localvmhost:
|32571|10:10|new| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x localvmhost '/bin/rm -rf 0' 2>&1
2010-04-28 09:53:54|32571|10:10|new|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|32571|10:10|new| none
2010-04-28 09:53:54|32571|10:10|new|utils.pm:run_ssh_command(6276)|SSH command executed on localvmhost, returning (0, "none")
2010-04-28 09:53:54|32571|10:10|new|vmware.pm:control_VM(1709)|removed 0 from localvmhost
2010-04-28 09:53:54|32571|10:10|new|DataStructure.pm:get_computer_private_ip_address(1442)|attempting to retrieve private IP address for computer: vmguest-1
2010-04-28 09:53:54|32571|10:10|new|DataStructure.pm:get_computer_private_ip_address(1446)|retrieved contents of /etc/hosts on this management node, contains 13 lines
2010-04-28 09:53:54|32571|10:10|new|DataStructure.pm:get_computer_private_ip_address(1479)|found line for 'vmguest-1' in /etc/hosts:
|32571|10:10|new| 192.168.1.1 vmguest-1
2010-04-28 09:53:54|32571|10:10|new|DataStructure.pm:get_computer_private_ip_address(1490)|found IP address: 192.168.1.1
2010-04-28 09:53:54|32571|10:10|new|DataStructure.pm:_automethod(697)|data structure updated: $self->request_data->{reservation}{10}{computer}{privateIPaddress}
|32571|10:10|new| computer_private_ip_address = 192.168.1.1
2010-04-28 09:53:54|32571|10:10|new|utils.pm:insertloadlog(4710)|inserted computer=2, startload, vmguest-1 vmwarelinux-xubuntu904-v0
2010-04-28 09:53:54|32571|10:10|new|vmware.pm:load(216)|identity file set /etc/vcl/vcl.key vmhost imagename noimage bladekey /etc/vcl/vcl.key
2010-04-28 09:53:54|32571|10:10|new|vmware.pm:load(244)|persistent= 0
2010-04-28 09:53:54|32571|10:10|new|vmware.pm:load(245)|myvmdir= vmwarelinux-xubuntu904-v0vmguest-1
2010-04-28 09:53:54|32571|10:10|new|vmware.pm:load(246)|myvmx= /home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx
2010-04-28 09:53:54|32571|10:10|new|vmware.pm:load(247)|mybasedirname= vmwarelinux-xubuntu904-v0
2010-04-28 09:53:54|32571|10:10|new|vmware.pm:load(248)|myimagename= vmwarelinux-xubuntu904-v0
2010-04-28 09:53:54|32571|10:10|new|vmware.pm:load(251)|checking for base image vmwarelinux-xubuntu904-v0vmguest-1 on localvmhost
2010-04-28 09:53:54|32571|10:10|new|utils.pm:insertloadlog(4710)|inserted computer=2, vmround1, checking host for requested image files
2010-04-28 09:53:54|32571|10:10|new|vmware.pm:load(256)|trying to create exclusive lock on /tmp/localvmhostvmwarelinux-xubuntu904-v0lock while checking if image files exist on host
2010-04-28 09:53:54|32571|10:10|new|vmware.pm:load(259)|owning exclusive lock on /tmp/localvmhostvmwarelinux-xubuntu904-v0lock
2010-04-28 09:53:54|32571|10:10|new|vmware.pm:load(260)|listing datestore /images/vmware
2010-04-28 09:53:54|32571|10:10|new|utils.pm:run_ssh_command(6180)|executing SSH command on localvmhost:
|32571|10:10|new| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x localvmhost 'ls -1 /images/vmware' 2>&1
2010-04-28 09:53:54|32571|10:10|new|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|32571|10:10|new| none
2010-04-28 09:53:54|32571|10:10|new|utils.pm:run_ssh_command(6276)|SSH command executed on localvmhost, returning (0, "none")
2010-04-28 09:53:54|32571|10:10|new|vmware.pm:load(270)|data store contents /images/vmware on vm host:
|32571|10:10|new| none
2010-04-28 09:53:54|32571|10:10|new|utils.pm:insertloadlog(4710)|inserted computer=2, info, image files do not exist on host server, preparing to copy
2010-04-28 09:53:54|32571|10:10|new|vmware.pm:load(360)|file size 2987340 of vmwarelinux-xubuntu904-v0
2010-04-28 09:53:54|32571|10:10|new|vmware.pm:load(361)|checking space on localvmhost /home/vm/vmware
2010-04-28 09:53:54|32571|10:10|new|utils.pm:run_ssh_command(6180)|executing SSH command on localvmhost:
|32571|10:10|new| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x localvmhost 'df -k /home/vm/vmware' 2>&1
2010-04-28 09:53:54|32571|10:10|new|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|32571|10:10|new| Filesystem 1K-blocks Used Available Use% Mounted on
|32571|10:10|new| /dev/sda5 145945192 85258004 60687188 59% /home
2010-04-28 09:53:54|32571|10:10|new|utils.pm:run_ssh_command(6276)|SSH command executed on localvmhost, returning (0, "Filesystem 1K-blocks Used Avai...")
2010-04-28 09:53:54|32571|10:10|new|vmware.pm:load(370)|datastore space available on remote machine 60687188
2010-04-28 09:53:54|32571|10:10|new|vmware.pm:load(466)|copying base image files vmwarelinux-xubuntu904-v0 to localvmhost
2010-04-28 09:53:54|32571|10:10|new|utils.pm:run_scp_command(6403)|attempt 1/3: executing SCP command: /usr/bin/scp -B -i /etc/vcl/vcl.key -P 22 -p -r /home/vm/vmware/vmwarelinux-xubuntu904-v0 localvmhost:"/images/vmware/vmwarelinux-xubuntu904-v0" 2>&1
2010-04-28 09:53:57|32550|vcld:main(165)|lastcheckin time updated for management node 1: 2010-04-28 09:53:57
...
2010-04-28 09:57:33|32550|vcld:main(165)|lastcheckin time updated for management node 1: 2010-04-28 09:57:33
2010-04-28 09:57:34|32571|10:10|new|utils.pm:run_scp_command(6453)|scp successful: attempt 1/3, exit status: 0, output: none
2010-04-28 09:57:34|32571|10:10|new|utils.pm:run_ssh_command(6180)|executing SSH command on localvmhost:
|32571|10:10|new| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x localvmhost 'ls -1 /images/vmware' 2>&1
2010-04-28 09:57:34|32571|10:10|new|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|32571|10:10|new| vmwarelinux-xubuntu904-v0
2010-04-28 09:57:34|32571|10:10|new|utils.pm:run_ssh_command(6276)|SSH command executed on localvmhost, returning (0, "vmwarelinux-xubuntu904-v0")
2010-04-28 09:57:34|32571|10:10|new|vmware.pm:load(480)|base image exists
2010-04-28 09:57:34|32571|10:10|new|utils.pm:insertloadlog(4710)|inserted computer=2, transfervm, copying base image files
2010-04-28 09:57:34|32571|10:10|new|vmware.pm:load(521)|confirm image exist process complete removing lock on /tmp/localvmhostvmwarelinux-xubuntu904-v0lock
2010-04-28 09:57:34|32571|10:10|new|vmware.pm:load(590)|created tmp directory /tmp/vmwarelinux-xubuntu904-v0vmguest-1
|32571|10:10|new| ---- WARNING ----
|32571|10:10|new| 2010-04-28 09:57:34|32571|10:10|new|vmware.pm:load(614)|image memory value 512 out of the expected range in host machine 2048 setting to 512
|32571|10:10|new| ( 0) utils.pm, notify (line: 737)
|32571|10:10|new| (-1) vmware.pm, load (line: 614)
|32571|10:10|new| (-2) new.pm, reload_image (line: 665)
|32571|10:10|new| (-3) new.pm, process (line: 266)
|32571|10:10|new| (-4) vcld, make_new_child (line: 594)
|32571|10:10|new| (-5) vcld, main (line: 341)
2010-04-28 09:57:34|32571|10:10|new|vmware.pm:load(621)|hda flag set, setting adapter to ide
2010-04-28 09:57:34|32571|10:10|new|vmware.pm:load(645)|adapter= ide drivetype hda
2010-04-28 09:57:34|32571|10:10|new|vmware.pm:load(722)|wrote vmxarray to /tmp/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx
2010-04-28 09:57:34|32571|10:10|new|utils.pm:insertloadlog(4710)|inserted computer=2, vmconfigcopy, transferring vmx file to localvmhost
2010-04-28 09:57:34|32571|10:10|new|utils.pm:run_scp_command(6403)|attempt 1/3: executing SCP command: /usr/bin/scp -B -i /etc/vcl/vcl.key -P 22 -p -r /tmp/vmwarelinux-xubuntu904-v0vmguest-1 localvmhost:"/home/vm/vmware" 2>&1
2010-04-28 09:57:35|32571|10:10|new|utils.pm:run_scp_command(6453)|scp successful: attempt 1/3, exit status: 0, output: none
2010-04-28 09:57:35|32571|10:10|new|utils.pm:run_ssh_command(6180)|executing SSH command on localvmhost:
|32571|10:10|new| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x localvmhost 'ls -1 /home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1;chmod 755 /home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx' 2>&1
2010-04-28 09:57:35|32571|10:10|new|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|32571|10:10|new| vmwarelinux-xubuntu904-v0vmguest-1.vmx
2010-04-28 09:57:35|32571|10:10|new|utils.pm:run_ssh_command(6276)|SSH command executed on localvmhost, returning (0, "vmwarelinux-xubuntu904-v0vmgue...")
2010-04-28 09:57:35|32571|10:10|new|vmware.pm:load(738)|successfully copied vmx file to localvmhost
2010-04-28 09:57:35|32571|10:10|new|utils.pm:insertloadlog(4710)|inserted computer=2, vmsetupconfig, setting up vmx file
2010-04-28 09:57:35|32571|10:10|new|vmware.pm:load(759)|successfully removed /tmp/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx
2010-04-28 09:57:35|32571|10:10|new|vmware.pm:load(760)|successfully removed tmp directory
2010-04-28 09:57:35|32571|10:10|new|utils.pm:run_ssh_command(6180)|executing SSH command on localvmhost:
|32571|10:10|new| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x localvmhost 'vmware-cmd -s register /home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx' 2>&1
2010-04-28 09:57:35|32571|10:10|new|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|32571|10:10|new| register(/home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx) = 1
2010-04-28 09:57:35|32571|10:10|new|utils.pm:run_ssh_command(6276)|SSH command executed on localvmhost, returning (0, "register(/home/vm/vmware/vmwar...")
2010-04-28 09:57:35|32571|10:10|new|vmware.pm:load(774)|vm /home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx registered
2010-04-28 09:57:35|32571|10:10|new|vmware.pm:load(796)|starting vm /home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx - pass 1
2010-04-28 09:57:35|32571|10:10|new|utils.pm:run_ssh_command(6180)|executing SSH command on localvmhost:
|32571|10:10|new| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x localvmhost 'vmware-cmd /home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx start' 2>&1
2010-04-28 09:57:36|32571|10:10|new|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|32571|10:10|new| VMControl error -16: Virtual machine requires user input to continue
2010-04-28 09:57:36|32571|10:10|new|utils.pm:run_ssh_command(6272)|SSH command executed on localvmhost, command:
|32571|10:10|new| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x localvmhost 'vmware-cmd /home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx start' 2>&1
|32571|10:10|new| returning (16, "VMControl error -16: Virtual m...")
2010-04-28 09:57:36|32571|10:10|new|vmware.pm:load(812)|vmware-cmd start failed
|32571|10:10|new| VMControl error -16: Virtual machine requires user input to continue
|32571|10:10|new| ---- WARNING ----
|32571|10:10|new| 2010-04-28 09:57:36|32571|10:10|new|new.pm:reload_image(670)|vmwarelinux-xubuntu904-v0 failed to load on vmguest-1, returning
|32571|10:10|new| ( 0) utils.pm, notify (line: 737)
|32571|10:10|new| (-1) new.pm, reload_image (line: 670)
|32571|10:10|new| (-2) new.pm, process (line: 266)
|32571|10:10|new| (-3) vcld, make_new_child (line: 594)
|32571|10:10|new| (-4) vcld, main (line: 341)
2010-04-28 09:57:37|32571|10:10|new|utils.pm:insertloadlog(4710)|inserted computer=2, loadimagefailed, vmwarelinux-xubuntu904-v0 failed to load on vmguest-1
|32571|10:10|new| ---- WARNING ----
|32571|10:10|new| 2010-04-28 09:57:37|32571|10:10|new|new.pm:process(313)|failed to load vmguest-1 with vmwarelinux-xubuntu904-v0
|32571|10:10|new| ( 0) utils.pm, notify (line: 737)
|32571|10:10|new| (-1) new.pm, process (line: 313)
|32571|10:10|new| (-2) vcld, make_new_child (line: 594)
|32571|10:10|new| (-3) vcld, main (line: 341)
2010-04-28 09:57:37|32571|10:10|new|DataStructure.pm:get_computer_state_name(1946)|attempting to retrieve current state of computer vmguest-1 from the database
2010-04-28 09:57:37|32571|10:10|new|DataStructure.pm:get_computer_state_name(1977)|retrieved current state of computer vmguest-1 from the database: reloading
2010-04-28 09:57:37|32571|10:10|new|DataStructure.pm:_automethod(697)|data structure updated: $self->request_data->{reservation}{10}{computer}{state}{name}
|32571|10:10|new| computer_state_name = reloading
2010-04-28 09:57:37|32571|10:10|new|utils.pm:mail(1348)|SUCCESS -- Sending mail To: m...@vt.edu, PROBLEM -- State.pm
|32571|10:10|new| ---- CRITICAL ----
|32571|10:10|new| 2010-04-28 09:57:37|32571|10:10|new|State.pm:reservation_failed(290)|reservation failed on vmguest-1: process failed after trying to load or make available
|32571|10:10|new| ( 0) utils.pm, notify (line: 737)
|32571|10:10|new| (-1) State.pm, reservation_failed (line: 290)
|32571|10:10|new| (-2) new.pm, process (line: 316)
|32571|10:10|new| (-3) vcld, make_new_child (line: 594)
|32571|10:10|new| (-4) vcld, main (line: 341)
2010-04-28 09:57:37|32571|10:10|new|utils.pm:insertloadlog(4710)|inserted computer=2, failed, process failed after trying to load or make available
2010-04-28 09:57:37|32571|10:10|new|State.pm:reservation_failed(293)|inserted computerloadlog entry
2010-04-28 09:57:37|32571|10:10|new|State.pm:reservation_failed(301)|updated log ending value to 'failed', logid=9
2010-04-28 09:57:37|32571|10:10|new|utils.pm:update_computer_state(2228)|computer 2 state updated to: failed
2010-04-28 09:57:37|32571|10:10|new|State.pm:reservation_failed(312)|computer vmguest-1 (2) state set to failed
2010-04-28 09:57:37|32571|10:10|new|utils.pm:update_request_state(2186)|request 10 state updated to: failed, laststate to: new
2010-04-28 09:57:37|32571|10:10|new|State.pm:reservation_failed(325)|set request state to 'failed'/'new'
2010-04-28 09:57:37|32571|10:10|new|utils.pm:is_inblockrequest(6972)|zero rows were returned from database select
2010-04-28 09:57:37|32571|10:10|new|State.pm:reservation_failed(343)|vmguest-1 is NOT in blockcomputers table
2010-04-28 09:57:37|32571|10:10|new|State.pm:reservation_failed(346)|exiting 1
2010-04-28 09:57:37|32571|10:10|new|State.pm:DESTROY(905)|destructor called, ref($self)=VCL::new
2010-04-28 09:57:37|32571|10:10|new|utils.pm:delete_computerloadlog_reservation(7551)|removing computerloadlog entries matching loadstate = begin
2010-04-28 09:57:37|32571|10:10|new|utils.pm:delete_computerloadlog_reservation(7598)|deleted rows from computerloadlog for reservation id=10
2010-04-28 09:57:37|32571|10:10|new|State.pm:DESTROY(912)|removed computerloadlog rows with loadstate=begin for reservation
2010-04-28 09:57:37|32571|10:10|new|State.pm:DESTROY(924)|number of database handles state process created: 1
2010-04-28 09:57:37|32571|10:10|new|State.pm:DESTROY(933)|process has a database handle stored in $ENV{dbh}, attempting disconnect
2010-04-28 09:57:37|32571|10:10|new|State.pm:DESTROY(935)|$ENV{dbh}: database disconnect successful
2010-04-28 09:57:37|32571|10:10|new|State.pm:DESTROY(949)|VCL::new process 32571 exiting
2010-04-28 09:57:37|32550|vcld:REAPER(744)|VCL process exited for reservation 10
2010-04-28 09:57:37|32550|vcld:main(165)|lastcheckin time updated for management node 1: 2010-04-28 09:57:37
...
2010-04-28 10:08:38|32550|vcld:main(165)|lastcheckin time updated for management node 1: 2010-04-28 10:08:38
2010-04-28 10:08:42|32550|vcld:HUNTSMAN(690)|HUNTSMAN called: signal: TERM, pid: 32550, process exiting
