[Still looking for help with this.] I have obviously misconfigured something...
I have been working on a standalone system and have been systematically fixing errors I find in the logs. On the last attempt to make a reservation, the VMware Server virtual machine was unregistered and deleted. Needless to say it was definitely a surprise! I am enclosing vcld.log. The problem occurs at time 10:31:55. I am also enclosing selects from related tables. Your help in correcting this unexpected behavior would be greatly appreciated. == BEGIN vcld.log === =========================================================== OUTPUT for vcld run on 2010-04-20 10:31:22 =========================================================== 2010-04-20 10:31:22|25426|vcld:main(116)|vcld environment variable set to 1 for this process 2010-04-20 10:31:22|25426|utils.pm:rename_vcld_process(7901)|renamed process to 'vcld vcld' 2010-04-20 10:31:22|25426|utils.pm:get_management_node_info(6815)|management node info retrieved from database for localhost 2010-04-20 10:31:22|25426|vcld:main(127)|retrieved management node information from database 2010-04-20 10:31:22|25426|vcld:main(140)|management_node_id environment variable set: 1 2010-04-20 10:31:22|25426|vcld:main(148)|management node checkin interval is 5 seconds 2010-04-20 10:31:22|25426|vcld:main(149)|vcld started on localhost 2010-04-20 10:31:27|25426|vcld:main(165)|lastcheckin time updated for management node 1: 2010-04-20 10:31:27 2010-04-20 10:31:32|25426|vcld:main(165)|lastcheckin time updated for management node 1: 2010-04-20 10:31:32 2010-04-20 10:31:37|25426|vcld:main(165)|lastcheckin time updated for management node 1: 2010-04-20 10:31:37 2010-04-20 10:31:42|25426|vcld:main(165)|lastcheckin time updated for management node 1: 2010-04-20 10:31:42 2010-04-20 10:31:47|25426|vcld:main(165)|lastcheckin time updated for management node 1: 2010-04-20 10:31:47 2010-04-20 10:31:52|25426|vcld:main(165)|lastcheckin time updated for management node 1: 2010-04-20 10:31:52 2010-04-20 10:31:52|25426|7:7|new|utils.pm:reservation_being_processed(9634)|computerloadlog 'begin' entry does NOT exist for reservation 7 2010-04-20 10:31:52|25426|7:7|new|utils.pm:reservation_being_processed(9686)|reservation is NOT currently being processed 2010-04-20 10:31:52|25426|7:7|new|vcld:main(276)|reservation 7 is NOT already being processed 2010-04-20 10:31:52|25426|7:7|new|utils.pm:get_request_info(5354)|standalone affiliation found: Local 2010-04-20 10:31:52|25426|7:7|new|utils.pm:get_management_node_info(6815)|management node info retrieved from database for localhost 2010-04-20 10:31:52|25426|7:7|new|vcld:main(281)|retrieved request information from database 2010-04-20 10:31:52|25426|7:7|new|utils.pm:get_management_node_info(6815)|management node info retrieved from database for localhost 2010-04-20 10:31:52|25426|7:7|new|DataStructure.pm:is_parent_reservation(854)|returning true: parent reservation ID for this request: 7 2010-04-20 10:31:52|25426|7:7|new|utils.pm:update_request_state(2186)|request 7 state updated to: pending, laststate to: new 2010-04-20 10:31:52|25426|7:7|new|utils.pm:insertloadlog(4710)|inserted computer=2, begin, beginning to process, state is new 2010-04-20 10:31:52|25426|7:7|new|vcld:make_new_child(509)|loaded VCL::new module 2010-04-20 10:31:52|25426|7:7|new|vcld:make_new_child(566)|current number of forked kids: 1 2010-04-20 10:31:52|25440|7:7|new|vcld:make_new_child(582)|vcld environment variable set to 0 for this process 2010-04-20 10:31:52|25440|7:7|new|Module.pm:new(132)|constructor called, class=VCL::new 2010-04-20 10:31:52|25440|7:7|new|Module.pm:new(154)|VCL::new object created 2010-04-20 10:31:52|25440|7:7|new|State.pm:initialize(85)|obtained a database handle for this state process, stored as $ENV{dbh} 2010-04-20 10:31:52|25440|7:7|new|State.pm:check_image_os(820)|no corrections need to be made, not an imaging request, returning 1 2010-04-20 10:31:52|25440|7:7|new|DataStructure.pm:is_parent_reservation(854)|returning true: parent reservation ID for this request: 7 2010-04-20 10:31:52|25440|7:7|new|utils.pm:rename_vcld_process(7863)|reservation count: 1 2010-04-20 10:31:52|25440|7:7|new|utils.pm:rename_vcld_process(7882)|PARENTIMAGE: 1 2010-04-20 10:31:52|25440|7:7|new|utils.pm:rename_vcld_process(7883)|SUBIMAGE: 0 2010-04-20 10:31:52|25440|7:7|new|utils.pm:rename_vcld_process(7901)|renamed process to 'vcld VCL::new 7:7 new' 2010-04-20 10:31:52|25440|7:7|new|DataStructure.pm:is_parent_reservation(854)|returning true: parent reservation ID for this request: 7 2010-04-20 10:31:52|25440|7:7|new|DataStructure.pm:is_parent_reservation(854)|returning true: parent reservation ID for this request: 7 2010-04-20 10:31:52|25440|7:7|new|State.pm:initialize(121)|attempting to load provisioning module: VCL::Module::Provisioning::vmware 2010-04-20 10:31:52|25440|7:7|new|State.pm:initialize(127)|VCL::Module::Provisioning::vmware module loaded 2010-04-20 10:31:52|25440|7:7|new|Module.pm:new(132)|constructor called, class=VCL::Module::Provisioning::vmware 2010-04-20 10:31:52|25440|7:7|new|Module.pm:new(154)|VCL::Module::Provisioning::vmware object created 2010-04-20 10:31:52|25440|7:7|new|vmware.pm:initialize(105)|vmware module initialized 2010-04-20 10:31:52|25440|7:7|new|State.pm:initialize(131)|VCL::Module::Provisioning::vmware provisioner object created 2010-04-20 10:31:52|25440|7:7|new|State.pm:initialize(145)|attempting to load OS module: VCL::Module::OS::Linux 2010-04-20 10:31:52|25440|7:7|new|State.pm:initialize(151)|VCL::Module::OS::Linux module loaded 2010-04-20 10:31:52|25440|7:7|new|Module.pm:new(132)|constructor called, class=VCL::Module::OS::Linux 2010-04-20 10:31:52|25440|7:7|new|Module.pm:new(154)|VCL::Module::OS::Linux object created 2010-04-20 10:31:52|25440|7:7|new|State.pm:initialize(154)|VCL::Module::OS::Linux OS object created 2010-04-20 10:31:52|25440|7:7|new|State.pm:initialize(169)|returning 1 2010-04-20 10:31:52|25440|7:7|new|vcld:make_new_child(591)|VCL::new object created and initialized 2010-04-20 10:31:52|25440|7:7|new|DataStructure.pm:is_parent_reservation(854)|returning true: parent reservation ID for this request: 7 2010-04-20 10:31:52|25440|7:7|new|DataStructure.pm:get_computer_state_name(1946)|attempting to retrieve current state of computer vmguest-1 from the database 2010-04-20 10:31:52|25440|7:7|new|DataStructure.pm:get_computer_state_name(1977)|retrieved current state of computer vmguest-1 from the database: available 2010-04-20 10:31:52|25440|7:7|new|DataStructure.pm:_automethod(697)|data structure updated: $self->request_data->{reservation}{7}{computer}{state}{name} |25440|7:7|new| computer_state_name = available 2010-04-20 10:31:52|25440|7:7|new|utils.pm:get_management_node_id(9364)|environment variable: 1 2010-04-20 10:31:52|25440|7:7|new|new.pm:process(134)|reservation is parent = 1 2010-04-20 10:31:52|25440|7:7|new|new.pm:process(135)|preload only = 0 2010-04-20 10:31:52|25440|7:7|new|new.pm:process(136)|originating request state = new 2010-04-20 10:31:52|25440|7:7|new|new.pm:process(137)|originating request laststate = new 2010-04-20 10:31:52|25440|7:7|new|new.pm:process(138)|originating computer state = available 2010-04-20 10:31:52|25440|7:7|new|new.pm:process(139)|originating computer type = virtualmachine 2010-04-20 10:31:52|25440|7:7|new|DataStructure.pm:is_parent_reservation(854)|returning true: parent reservation ID for this request: 7 2010-04-20 10:31:52|25440|7:7|new|DataStructure.pm:get_computer_state_name(1946)|attempting to retrieve current state of computer vmguest-1 from the database 2010-04-20 10:31:52|25440|7:7|new|DataStructure.pm:get_computer_state_name(1977)|retrieved current state of computer vmguest-1 from the database: available 2010-04-20 10:31:52|25440|7:7|new|DataStructure.pm:_automethod(697)|data structure updated: $self->request_data->{reservation}{7}{computer}{state}{name} |25440|7:7|new| computer_state_name = available 2010-04-20 10:31:52|25440|7:7|new|utils.pm:get_management_node_id(9364)|environment variable: 1 2010-04-20 10:31:52|25440|7:7|new|new.pm:computer_not_being_used(788)|vmguest-1 state is available 2010-04-20 10:31:52|25440|7:7|new|new.pm:computer_not_being_used(798)|vmguest-1 is available, its state is available 2010-04-20 10:31:52|25440|7:7|new|new.pm:process(170)|vmguest-1 is not being used 2010-04-20 10:31:52|25440|7:7|new|DataStructure.pm:is_parent_reservation(854)|returning true: parent reservation ID for this request: 7 2010-04-20 10:31:52|25440|7:7|new|DataStructure.pm:get_computer_state_name(1946)|attempting to retrieve current state of computer vmguest-1 from the database 2010-04-20 10:31:52|25440|7:7|new|DataStructure.pm:get_computer_state_name(1977)|retrieved current state of computer vmguest-1 from the database: available 2010-04-20 10:31:52|25440|7:7|new|DataStructure.pm:_automethod(697)|data structure updated: $self->request_data->{reservation}{7}{computer}{state}{name} |25440|7:7|new| computer_state_name = available 2010-04-20 10:31:52|25440|7:7|new|utils.pm:get_management_node_id(9364)|environment variable: 1 2010-04-20 10:31:52|25440|7:7|new|new.pm:reload_image(514)|calling VCL::Module::Provisioning::vmware->node_status() 2010-04-20 10:31:52|25440|7:7|new|utils.pm:insertloadlog(4710)|inserted computer=2, statuscheck, checking status of node 2010-04-20 10:31:52|25440|7:7|new|vmware.pm:node_status(1888)|identity_keys= /etc/vcl/vcl.key 2010-04-20 10:31:52|25440|7:7|new|vmware.pm:node_status(1889)|requestedimagename= vmwarelinux-xubuntu904-v0 2010-04-20 10:31:52|25440|7:7|new|vmware.pm:node_status(1890)|image_os_type= linux 2010-04-20 10:31:52|25440|7:7|new|vmware.pm:node_status(1891)|request_forimaging= 0 2010-04-20 10:31:52|25440|7:7|new|vmware.pm:node_status(1892)|vmpath= /images/vmware 2010-04-20 10:31:52|25440|7:7|new|vmware.pm:node_status(1893)|datastorepath= /images/vmware 2010-04-20 10:31:52|25440|7:7|new|vmware.pm:node_status(1911)|checking if vmguest-1 is pingable 2010-04-20 10:31:52|25440|7:7|new|vmware.pm:node_status(1914)|vmguest-1 is pingable (1) 2010-04-20 10:31:52|25440|7:7|new|utils.pm:run_ssh_command(6180)|executing SSH command on localvmhost: |25440|7:7|new| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x localvmhost 'vmware-cmd /images/vmware/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx getstate' 2>&1 2010-04-20 10:31:53|25440|7:7|new|utils.pm:run_ssh_command(6262)|run_ssh_command output: |25440|7:7|new| getstate() = on 2010-04-20 10:31:53|25440|7:7|new|utils.pm:run_ssh_command(6276)|SSH command executed on localvmhost, returning (0, "getstate() = on") 2010-04-20 10:31:53|25440|7:7|new|vmware.pm:node_status(1930)|getstate() = on 2010-04-20 10:31:53|25440|7:7|new|vmware.pm:node_status(1941)|vmguest-1 vmstate reports on 2010-04-20 10:31:53|25440|7:7|new|vmware.pm:node_status(1979)|returning node status hash reference ($node_status->{status}=RELOAD) 2010-04-20 10:31:53|25440|7:7|new|new.pm:reload_image(529)|node_status returned a hash reference 2010-04-20 10:31:53|25440|7:7|new|new.pm:reload_image(534)|node_status hash reference contains key {status}=RELOAD 2010-04-20 10:31:53|25440|7:7|new|new.pm:reload_image(602)|node status is RELOAD, vmguest-1 will be reloaded 2010-04-20 10:31:53|25440|7:7|new|utils.pm:insertloadlog(4710)|inserted computer=2, loadimageblade, vmguest-1 must be reloaded with vmwarelinux-xubuntu904-v0 2010-04-20 10:31:53|25440|7:7|new|new.pm:reload_image(616)|calling VCL::Module::Provisioning::vmware->does_image_exist() 2010-04-20 10:31:53|25440|7:7|new|vmware.pm:does_image_exist(2018)|image repository path: /images/vmware 2010-04-20 10:31:53|25440|7:7|new|utils.pm:run_command(9737)|executed command: du -c /images/vmware/*vmwarelinux-xubuntu904-v0* 2>&1 | grep total 2>&1, pid: 25451, exit status: 0, output: |25440|7:7|new| 2701668 total 2010-04-20 10:31:53|25440|7:7|new|vmware.pm:does_image_exist(2070)|vmwarelinux-xubuntu904-v0 exists in /images/vmware, size: 2638 MB 2010-04-20 10:31:53|25440|7:7|new|new.pm:reload_image(619)|vmwarelinux-xubuntu904-v0 exists on this management node 2010-04-20 10:31:54|25440|7:7|new|utils.pm:insertloadlog(4710)|inserted computer=2, doesimageexists, confirmed image exists 2010-04-20 10:31:54|25440|7:7|new|utils.pm:update_computer_state(2228)|computer 2 state updated to: reloading 2010-04-20 10:31:54|25440|7:7|new|new.pm:reload_image(652)|computer vmguest-1 state set to reloading 2010-04-20 10:31:54|25440|7:7|new|utils.pm:insertloadlog(4710)|inserted computer=2, info, computer state updated to reloading 2010-04-20 10:31:54|25440|7:7|new|new.pm:reload_image(663)|calling VCL::Module::Provisioning::vmware->load() subroutine 2010-04-20 10:31:54|25440|7:7|new|utils.pm:insertloadlog(4710)|inserted computer=2, info, calling VCL::Module::Provisioning::vmware->load() subroutine 2010-04-20 10:31:54|25440|7:7|new|vmware.pm:control_VM(1526)|control remove is defined 2010-04-20 10:31:54|25440|7:7|new|vmware.pm:control_VM(1590)|checking for base image on localvmhost /images/vmware 2010-04-20 10:31:54|25440|7:7|new|utils.pm:run_ssh_command(6180)|executing SSH command on localvmhost: |25440|7:7|new| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x localvmhost 'ls -1 /images/vmware' 2>&1 2010-04-20 10:31:54|25440|7:7|new|utils.pm:run_ssh_command(6262)|run_ssh_command output: |25440|7:7|new| XUbuntu_LiveCD |25440|7:7|new| vmwarelinux-xubuntu904-v0vmguest-1 |25440|7:7|new| vmwarelinux-xubuntu910-v0 2010-04-20 10:31:54|25440|7:7|new|utils.pm:run_ssh_command(6276)|SSH command executed on localvmhost, returning (0, "XUbuntu_LiveCD vmwarelinux-xub...") 2010-04-20 10:31:54|25440|7:7|new|vmware.pm:control_VM(1596)|XUbuntu_LiveCD vmwarelinux-xubuntu904-v0vmguest-1 vmwarelinux-xubuntu910-v0 2010-04-20 10:31:54|25440|7:7|new|vmware.pm:control_VM(1618)|/images/vmware/noimagevmguest-1/noimagevmguest-1.vmx directory structure for noimagevmguest-1 did not exist 2010-04-20 10:31:54|25440|7:7|new|utils.pm:run_ssh_command(6180)|executing SSH command on localvmhost: |25440|7:7|new| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x localvmhost 'vmware-cmd -l' 2>&1 2010-04-20 10:31:54|25440|7:7|new|utils.pm:run_ssh_command(6262)|run_ssh_command output: |25440|7:7|new| /home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx 2010-04-20 10:31:54|25440|7:7|new|utils.pm:run_ssh_command(6276)|SSH command executed on localvmhost, returning (0, "/home/vm/vmware/vmwarelinux-xu...") 2010-04-20 10:31:54|25440|7:7|new|vmware.pm: control_VM(1636)|/home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx 2010-04-20 10:31:54|25440|7:7|new|vmware.pm:control_VM(1644)|my vmx /home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx 2010-04-20 10:31:54|25440|7:7|new|utils.pm:run_ssh_command(6180)|executing SSH command on localvmhost: |25440|7:7|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-20 10:31:55|25440|7:7|new|utils.pm:run_ssh_command(6262)|run_ssh_command output: |25440|7:7|new| getstate() = on 2010-04-20 10:31:55|25440|7:7|new|utils.pm:run_ssh_command(6276)|SSH command executed on localvmhost, returning (0, "getstate() = on") 2010-04-20 10:31:55|25440|7:7|new|utils.pm:run_ssh_command(6180)|executing SSH command on localvmhost: |25440|7:7|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 stop hard' 2>&1 2010-04-20 10:31:55|25440|7:7|new|utils.pm:run_ssh_command(6262)|run_ssh_command output: |25440|7:7|new| stop(hard) = 1 2010-04-20 10:31:55|25440|7:7|new|utils.pm:run_ssh_command(6276)|SSH command executed on localvmhost, returning (0, "stop(hard) = 1") 2010-04-20 10:31:55|25440|7:7|new|vmware.pm:control_VM(1662)|turned off /home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx 2010-04-20 10:31:55|25440|7:7|new|utils.pm:run_ssh_command(6180)|executing SSH command on localvmhost: |25440|7:7|new| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x localvmhost 'vmware-cmd -s unregister /home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx ' 2>&1 2010-04-20 10:31:55|25440|7:7|new|utils.pm:run_ssh_command(6262)|run_ssh_command output: |25440|7:7|new| unregister(/home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx) = 1 2010-04-20 10:31:55|25440|7:7|new|utils.pm:run_ssh_command(6276)|SSH command executed on localvmhost, returning (0, "unregister(/home/vm/vmware/vmw...") 2010-04-20 10:31:55|25440|7:7|new|vmware.pm:control_VM(1702)|vm /home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx unregistered 2010-04-20 10:31:55|25440|7:7|new|utils.pm:run_ssh_command(6180)|executing SSH command on localvmhost: |25440|7:7|new| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x localvmhost '/bin/rm -rf /home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1' 2>&1 2010-04-20 10:31:56|25440|7:7|new|utils.pm:run_ssh_command(6262)|run_ssh_command output: |25440|7:7|new| none 2010-04-20 10:31:56|25440|7:7|new|utils.pm:run_ssh_command(6276)|SSH command executed on localvmhost, returning (0, "none") 2010-04-20 10:31:56|25440|7:7|new|vmware.pm:control_VM(1709)|removed /home/vm/vmware/vmwarelinux-xubuntu904-v0vmguest-1 from localvmhost 2010-04-20 10:31:56|25440|7:7|new|DataStructure.pm:get_computer_private_ip_address(1442)|attempting to retrieve private IP address for computer: vmguest-1 2010-04-20 10:31:56|25440|7:7|new|DataStructure.pm:get_computer_private_ip_address(1446)|retrieved contents of /etc/hosts on this management node, contains 13 lines 2010-04-20 10:31:56|25440|7:7|new|DataStructure.pm:get_computer_private_ip_address(1479)|found line for 'vmguest-1' in /etc/hosts: |25440|7:7|new| 192.168.1.1 vmguest-1 2010-04-20 10:31:56|25440|7:7|new|DataStructure.pm:get_computer_private_ip_address(1490)|found IP address: 192.168.1.1 2010-04-20 10:31:56|25440|7:7|new|DataStructure.pm:_automethod(697)|data structure updated: $self->request_data->{reservation}{7}{computer}{privateIPaddress} |25440|7:7|new| computer_private_ip_address = 192.168.1.1 2010-04-20 10:31:56|25440|7:7|new|utils.pm:insertloadlog(4710)|inserted computer=2, startload, vmguest-1 vmwarelinux-xubuntu904-v0 2010-04-20 10:31:56|25440|7:7|new|vmware.pm:load(216)|identity file set /etc/vcl/vcl.key vmhost imagename noimage bladekey /etc/vcl/vcl.key 2010-04-20 10:31:56|25440|7:7|new|vmware.pm:load(244)|persistent= 0 2010-04-20 10:31:56|25440|7:7|new|vmware.pm:load(245)|myvmdir= vmwarelinux-xubuntu904-v0vmguest-1 2010-04-20 10:31:56|25440|7:7|new|vmware.pm:load(246)|myvmx= /images/vmware/vmwarelinux-xubuntu904-v0vmguest-1/vmwarelinux-xubuntu904-v0vmguest-1.vmx 2010-04-20 10:31:56|25440|7:7|new|vmware.pm:load(247)|mybasedirname= vmwarelinux-xubuntu904-v0 2010-04-20 10:31:56|25440|7:7|new|vmware.pm:load(248)|myimagename= vmwarelinux-xubuntu904-v0 2010-04-20 10:31:56|25440|7:7|new|vmware.pm:load(251)|checking for base image vmwarelinux-xubuntu904-v0vmguest-1 on localvmhost 2010-04-20 10:31:56|25440|7:7|new|utils.pm:insertloadlog(4710)|inserted computer=2, vmround1, checking host for requested image files 2010-04-20 10:31:56|25440|7:7|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-20 10:31:56|25440|7:7|new|vmware.pm:load(259)|owning exclusive lock on /tmp/localvmhostvmwarelinux-xubuntu904-v0lock 2010-04-20 10:31:56|25440|7:7|new|vmware.pm:load(260)|listing datestore /images/vmware 2010-04-20 10:31:56|25440|7:7|new|utils.pm:run_ssh_command(6180)|executing SSH command on localvmhost: |25440|7:7|new| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x localvmhost 'ls -1 /images/vmware' 2>&1 2010-04-20 10:31:56|25440|7:7|new|utils.pm:run_ssh_command(6262)|run_ssh_command output: |25440|7:7|new| XUbuntu_LiveCD |25440|7:7|new| vmwarelinux-xubuntu910-v0 2010-04-20 10:31:56|25440|7:7|new|utils.pm:run_ssh_command(6276)|SSH command executed on localvmhost, returning (0, "XUbuntu_LiveCD vmwarelinux-xub...") 2010-04-20 10:31:56|25440|7:7|new|vmware.pm:load(270)|data store contents /images/vmware on vm host: |25440|7:7|new| XUbuntu_LiveCD vmwarelinux-xubuntu910-v0 2010-04-20 10:31:56|25440|7:7|new|utils.pm:insertloadlog(4710)|inserted computer=2, info, image files do not exist on host server, preparing to copy 2010-04-20 10:31:56|25440|7:7|new|utils.pm:insertloadlog(4710)|inserted computer=2, failed, could not collect size of local image files 2010-04-20 10:31:56|25440|7:7|new|utils.pm:mail(1348)|SUCCESS -- Sending mail To: m...@vt.edu, PROBLEM -- vmware.pm |25440|7:7|new| ---- CRITICAL ---- |25440|7:7|new| 2010-04-20 10:31:56|25440|7:7|new|vmware.pm:load(349)|problem checking local vm file size on /images/vmware/vmwarelinux-xubuntu904-v0 |25440|7:7|new| ( 0) utils.pm, notify (line: 737) |25440|7:7|new| (-1) vmware.pm, load (line: 349) |25440|7:7|new| (-2) new.pm, reload_image (line: 665) |25440|7:7|new| (-3) new.pm, process (line: 266) |25440|7:7|new| (-4) vcld, make_new_child (line: 594) |25440|7:7|new| (-5) vcld, main (line: 341) |25440|7:7|new| ---- WARNING ---- |25440|7:7|new| 2010-04-20 10:31:56|25440|7:7|new|new.pm:reload_image(670)|vmwarelinux-xubuntu904-v0 failed to load on vmguest-1, returning |25440|7:7|new| ( 0) utils.pm, notify (line: 737) |25440|7:7|new| (-1) new.pm, reload_image (line: 670) |25440|7:7|new| (-2) new.pm, process (line: 266) |25440|7:7|new| (-3) vcld, make_new_child (line: 594) |25440|7:7|new| (-4) vcld, main (line: 341) 2010-04-20 10:31:56|25440|7:7|new|utils.pm:insertloadlog(4710)|inserted computer=2, loadimagefailed, vmwarelinux-xubuntu904-v0 failed to load on vmguest-1 |25440|7:7|new| ---- WARNING ---- |25440|7:7|new| 2010-04-20 10:31:56|25440|7:7|new|new.pm:process(313)|failed to load vmguest-1 with vmwarelinux-xubuntu904-v0 |25440|7:7|new| ( 0) utils.pm, notify (line: 737) |25440|7:7|new| (-1) new.pm, process (line: 313) |25440|7:7|new| (-2) vcld, make_new_child (line: 594) |25440|7:7|new| (-3) vcld, main (line: 341) 2010-04-20 10:31:56|25440|7:7|new|DataStructure.pm:get_computer_state_name(1946)|attempting to retrieve current state of computer vmguest-1 from the database 2010-04-20 10:31:56|25440|7:7|new|DataStructure.pm:get_computer_state_name(1977)|retrieved current state of computer vmguest-1 from the database: reloading 2010-04-20 10:31:56|25440|7:7|new|DataStructure.pm:_automethod(697)|data structure updated: $self->request_data->{reservation}{7}{computer}{state}{name} |25440|7:7|new| computer_state_name = reloading 2010-04-20 10:31:56|25440|7:7|new|utils.pm:mail(1348)|SUCCESS -- Sending mail To: m...@vt.edu, PROBLEM -- State.pm |25440|7:7|new| ---- CRITICAL ---- |25440|7:7|new| 2010-04-20 10:31:56|25440|7:7|new|State.pm:reservation_failed(290)|reservation failed on vmguest-1: process failed after trying to load or make available |25440|7:7|new| ( 0) utils.pm, notify (line: 737) |25440|7:7|new| (-1) State.pm, reservation_failed (line: 290) |25440|7:7|new| (-2) new.pm, process (line: 316) |25440|7:7|new| (-3) vcld, make_new_child (line: 594) |25440|7:7|new| (-4) vcld, main (line: 341) 2010-04-20 10:31:56|25440|7:7|new|utils.pm:insertloadlog(4710)|inserted computer=2, failed, process failed after trying to load or make available 2010-04-20 10:31:56|25440|7:7|new|State.pm:reservation_failed(293)|inserted computerloadlog entry 2010-04-20 10:31:56|25440|7:7|new|State.pm:reservation_failed(301)|updated log ending value to 'failed', logid=6 2010-04-20 10:31:56|25440|7:7|new|utils.pm:update_computer_state(2228)|computer 2 state updated to: failed 2010-04-20 10:31:56|25440|7:7|new|State.pm:reservation_failed(312)|computer vmguest-1 (2) state set to failed 2010-04-20 10:31:56|25440|7:7|new|utils.pm:update_request_state(2186)|request 7 state updated to: failed, laststate to: new 2010-04-20 10:31:56|25440|7:7|new|State.pm:reservation_failed(325)|set request state to 'failed'/'new' 2010-04-20 10:31:56|25440|7:7|new|utils.pm:is_inblockrequest(6972)|zero rows were returned from database select 2010-04-20 10:31:56|25440|7:7|new|State.pm:reservation_failed(343)|vmguest-1 is NOT in blockcomputers table 2010-04-20 10:31:56|25440|7:7|new|State.pm:reservation_failed(346)|exiting 1 2010-04-20 10:31:56|25440|7:7|new|State.pm:DESTROY(905)|destructor called, ref($self)=VCL::new 2010-04-20 10:31:56|25440|7:7|new|utils.pm:delete_computerloadlog_reservation(7551)|removing computerloadlog entries matching loadstate = begin 2010-04-20 10:31:56|25440|7:7|new|utils.pm:delete_computerloadlog_reservation(7598)|deleted rows from computerloadlog for reservation id=7 2010-04-20 10:31:56|25440|7:7|new|State.pm:DESTROY(912)|removed computerloadlog rows with loadstate=begin for reservation 2010-04-20 10:31:56|25440|7:7|new|State.pm:DESTROY(924)|number of database handles state process created: 1 2010-04-20 10:31:56|25440|7:7|new|State.pm:DESTROY(933)|process has a database handle stored in $ENV{dbh}, attempting disconnect 2010-04-20 10:31:56|25440|7:7|new|State.pm:DESTROY(935)|$ENV{dbh}: database disconnect successful 2010-04-20 10:31:56|25440|7:7|new|State.pm:DESTROY(949)|VCL::new process 25440 exiting 2010-04-20 10:31:56|25426|vcld:REAPER(744)|VCL process exited for reservation 7 2010-04-20 10:31:56|25426|vcld:main(165)|lastcheckin time updated for management node 1: 2010-04-20 10:31:56 === END vcld.log === === BEGIN mysql tables === mysql> select * from computer; +----+---------+---------+------------+------------+----------------+------------------+-------------+-----------------+------+------------+-----------+---------+-------------+-------------+------------------+-------------------+-------------------+----------------+----------------+-----------+---------+-------+-----------+----------+------+--------+------+--------+------+---------+----------+----------+ | id | stateid | ownerid | platformid | scheduleid | currentimageid | preferredimageid | nextimageid | imagerevisionid | RAM | procnumber | procspeed | network | hostname | IPaddress | privateIPaddress | eth0macaddress | eth1macaddress | type | provisioningid | drivetype | deleted | notes | lastcheck | location | dsa | dsapub | rsa | rsapub | host | hostpub | vmhostid | vmtypeid | +----+---------+---------+------------+------------+----------------+------------------+-------------+-----------------+------+------------+-----------+---------+-------------+-------------+------------------+-------------------+-------------------+----------------+----------------+-----------+---------+-------+-----------+----------+------+--------+------+--------+------+---------+----------+----------+ | 1 | 2 | 1 | 1 | 1 | 4 | 0 | 0 | 0 | 2048 | 1 | 3000 | 100 | localvmhost | 192.168.0.1 | NULL | NULL | NULL | blade | 3 | hda | 0 | | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | | 2 | 2 | 1 | 1 | 1 | 4 | 10 | 0 | 0 | 512 | 1 | 2000 | 100 | vmguest-1 | 192.168.1.1 | NULL | 00:50:56:1a:01:01 | 00:50:56:1a:01:02 | virtualmachine | 2 | hda | 0 | | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | 1 | 3 | +----+---------+---------+------------+------------+----------------+------------------+-------------+-----------------+------+------------+-----------+---------+-------------+-------------+------------------+-------------------+-------------------+----------------+----------------+-----------+---------+-------+-----------+----------+------+--------+------+--------+------+---------+----------+----------+ 2 rows in set (0.00 sec) mysql> select * from OS; +----+----------------+-------------------------------------+---------+-------------+---------------+----------+ | id | name | prettyname | type | installtype | sourcepath | moduleid | +----+----------------+-------------------------------------+---------+-------------+---------------+----------+ | 2 | sun4x_58 | Solaris 5.8 | unix | none | NULL | 15 | | 3 | win2k | Windows 2000 | windows | partimage | image | 4 | | 6 | rhel3 | Red Hat Enterprise Linux 3.0 | linux | kickstart | rhas3 | 5 | | 7 | winxp | Windows XP | windows | partimage | image | 12 | | 8 | realmrhel3 | Realm Red Hat Enterprise Linux 3.0 | linux | none | NULL | 15 | | 9 | realmrhel4 | Realm Red Hat Enterprise Linux 4.0 | linux | none | NULL | 15 | | 10 | win2003 | Windows 2003 Server | windows | partimage | image | 13 | | 11 | rh3image | RHEL 3 image | linux | partimage | image | 5 | | 12 | rhel4 | Red Hat Enterprise Linux 4 | linux | kickstart | rhas4 | 5 | | 13 | rh4image | RHEL4 image | linux | partimage | image | 5 | | 14 | fc5image | RH Fedora Core 5 image | linux | partimage | image | 5 | | 15 | rhfc5 | Red Hat Fedora Core 5 | linux | kickstart | rhfc5 | 5 | | 16 | vmwarewinxp | VMware Windows XP | windows | vmware | vmware_images | 12 | | 17 | rhfc7 | RH Fedora Core 7 KS | linux | kickstart | rhfc7 | 5 | | 18 | fc7image | RH Fedora Core 7 image | linux | partimage | image | 5 | | 19 | rhel5 | Red Hat Enterprise Linux 5 | linux | kickstart | rhas5 | 5 | | 20 | esx35 | VMware ESX 3.5 | linux | kickstart | esx35 | 5 | | 21 | vmwareesxwinxp | VMware ESX Windows XP | windows | vmware | vmware_images | 12 | | 22 | realmrhel5 | Realm Red Hat Enterprise Linux 5.0 | linux | none | NULL | 15 | | 23 | sun4x_510 | Solaris 10 | unix | none | NULL | 15 | | 24 | centos5 | CentOS 5 | linux | kickstart | centos5 | 5 | | 25 | rh5image | RedHat Enterprise Linux 5 (rhel5 im | linux | partimage | image | 5 | | 26 | rhfc9 | RedHat Fedora Core 9 kickstart | linux | kickstart | rhfc9 | 5 | | 27 | fc9image | RedHat Fedora Core 9 image | linux | partimage | image | 5 | | 28 | winvista | Windows Vista | windows | partimage | image | 7 | | 29 | centos5image | centos5image | linux | partimage | image | 5 | | 30 | ubuntuimage | Ubuntu image | linux | partimage | image | 14 | | 31 | vmwarewin2008 | VMware Windows Server 2008 | windows | vmware | vmware_images | 16 | | 32 | win2008 | Windows Server 2008 | windows | partimage | image | 16 | | 33 | vmwarewinvista | VMware Windows Vista | windows | vmware | vmware_images | 7 | | 34 | vmwarelinux | VMware Generic Linux | linux | vmware | vmware | 5 | +----+----------------+-------------------------------------+---------+-------------+---------------+----------+ 31 rows in set (0.00 sec) mysql> select * from image; +----+------------------------------------+----------------------------------------+---------+------------+------+-------------+--------+---------------+--------------+------------+---------------+------------+---------+------+---------------------+-------------+----------------+---------+------+--------------+-------------+-------+--------------------+ | id | name | prettyname | ownerid | platformid | OSid | imagemetaid | minram | minprocnumber | minprocspeed | minnetwork | maxconcurrent | reloadtime | deleted | test | lastupdate | forcheckout | maxinitialtime | project | size | architecture | description | usage | basedoffrevisionid | +----+------------------------------------+----------------------------------------+---------+------------+------+-------------+--------+---------------+--------------+------------+---------------+------------+---------+------+---------------------+-------------+----------------+---------+------+--------------+-------------+-------+--------------------+ | 1 | winxp-base1-v0 | No Apps (WinXP) | 1 | 1 | 7 | NULL | 0 | 1 | 0 | 10 | NULL | 14 | 0 | 0 | 2007-04-11 16:07:38 | 1 | 0 | vcl | 1045 | x86 | NULL | NULL | 0 | | 2 | rhel4-base2-v0 | Red Hat Enterprise Linux 4.4 Base (KS) | 1 | 1 | 12 | NULL | 1024 | 1 | 1024 | 100 | NULL | 13 | 0 | 0 | 2007-03-02 16:33:33 | 1 | 0 | vcl | 0 | x86 | NULL | NULL | 0 | | 3 | rh4image-base3-v0 | RHEL4 base (image) | 1 | 1 | 13 | NULL | 10 | 1 | 1024 | 100 | NULL | 10 | 0 | 0 | 2007-01-24 15:02:07 | 1 | 0 | vcl | 1450 | x86 | NULL | NULL | 0 | | 4 | noimage | No Image | 1 | 1 | 2 | NULL | 0 | 1 | 0 | 10 | NULL | 0 | 0 | 0 | NULL | 1 | 0 | vcl | 1450 | x86 | NULL | NULL | 0 | | 5 | rhfc5-fc5base5-v0 | Red Hat Fedora Core 5 base (KS) | 1 | 1 | 15 | NULL | 1024 | 1 | 1024 | 100 | NULL | 13 | 0 | 0 | 2006-10-02 10:04:24 | 1 | 0 | vcl | 1450 | x86 | NULL | NULL | 0 | | 6 | fc5image-FC5baseRHFC56-v0 | FC5base(RHFC5) | 1 | 1 | 14 | NULL | 64 | 1 | 500 | 10 | NULL | 10 | 0 | 0 | 2006-10-02 14:13:26 | 1 | 0 | vcl | 0 | x86 | NULL | NULL | 0 | | 7 | vmwarewinxp-base7-v1 | No Apps (WinXP vmware) | 1 | 1 | 16 | NULL | 512 | 1 | 1024 | 100 | NULL | 5 | 0 | 0 | 2007-04-04 09:45:38 | 1 | 0 | vcl | 3244 | x86 | NULL | NULL | 0 | | 8 | rh4image-VMwareserverhostRHEL48-v3 | VMware server host (RHEL4) | 1 | 1 | 13 | NULL | 64 | 1 | 500 | 10 | NULL | 10 | 0 | 0 | 2007-11-26 11:23:53 | 1 | 0 | vcl | 1450 | x86 | NULL | NULL | 0 | | 9 | esx35-base-v0 | VMware ESX 3.5 standard server | 1 | 1 | 20 | NULL | 2048 | 2 | 2000 | 100 | NULL | 9 | 0 | 0 | 2008-03-24 14:23:54 | 1 | 0 | vcl | 1450 | x86 | NULL | NULL | 0 | | 10 | vmwarelinux-xubuntu904-v0 | No Apps (Linux, XUbuntu 9.04) | 1 | 1 | 34 | NULL | 512 | 1 | 1024 | 100 | NULL | 5 | 0 | 0 | 2010-04-19 12:00:28 | 1 | 0 | vcl | 1500 | x86 | NULL | NULL | 0 | +----+------------------------------------+----------------------------------------+---------+------------+------+-------------+--------+---------------+--------------+------------+---------------+------------+---------+------+---------------------+-------------+----------------+---------+------+--------------+-------------+-------+--------------------+ 10 rows in set (0.00 sec) mysql> select * from imagerevision; +----+---------+----------+--------+---------------------+---------+-------------+------------+----------+------------------------------------+ | id | imageid | revision | userid | datecreated | deleted | datedeleted | production | comments | imagename | +----+---------+----------+--------+---------------------+---------+-------------+------------+----------+------------------------------------+ | 1 | 1 | 0 | 1 | 2007-03-01 14:46:26 | 0 | NULL | 1 | NULL | winxp-base1-v0 | | 2 | 2 | 0 | 1 | 2006-09-22 16:33:24 | 0 | NULL | 1 | NULL | rhel4-base2-v0 | | 3 | 3 | 0 | 1 | 2007-01-24 15:04:11 | 0 | NULL | 1 | NULL | rh4image-base3-v0 | | 4 | 4 | 0 | 1 | 1980-01-01 00:00:00 | 0 | NULL | 1 | NULL | noimage | | 5 | 5 | 0 | 1 | 2006-10-02 10:04:24 | 0 | NULL | 1 | NULL | rhfc5-fc5base5-v0 | | 6 | 6 | 0 | 1 | 2006-10-02 14:13:26 | 0 | NULL | 1 | NULL | fc5image-FC5baseRHFC56-v0 | | 7 | 7 | 0 | 1 | 2007-04-03 11:24:12 | 0 | NULL | 1 | NULL | vmwarewinxp-base7-v0 | | 8 | 8 | 0 | 1 | 2007-01-30 10:50:56 | 0 | NULL | 1 | NULL | rh4image-VMwareserverhostRHEL48-v0 | | 9 | 9 | 0 | 1 | 2008-03-24 14:23:54 | 0 | NULL | 1 | NULL | esx35-base-v0 | | 10 | 10 | 1 | 1 | 2010-04-19 12:00:33 | 0 | NULL | 1 | NULL | vmwarelinux-xubuntu904-v0 | +----+---------+----------+--------+---------------------+---------+-------------+------------+----------+------------------------------------+ 10 rows in set (0.00 sec) mysql> select * from resource; +----+----------------+-------+ | id | resourcetypeid | subid | +----+----------------+-------+ | 12 | 12 | 1 | | 13 | 12 | 2 | | 1 | 13 | 1 | | 2 | 13 | 2 | | 3 | 13 | 3 | | 4 | 13 | 4 | | 5 | 13 | 5 | | 6 | 13 | 6 | | 7 | 13 | 7 | | 9 | 13 | 8 | | 10 | 13 | 9 | | 14 | 13 | 10 | | 8 | 15 | 1 | | 11 | 16 | 1 | +----+----------------+-------+ 14 rows in set (0.00 sec) mysql> select * from request; +----+---------+--------+-------------+-------+------------+------+---------+---------------------+---------------------+---------------------+--------------+ | id | stateid | userid | laststateid | logid | forimaging | test | preload | start | end | daterequested | datemodified | +----+---------+--------+-------------+-------+------------+------+---------+---------------------+---------------------+---------------------+--------------+ | 1 | 14 | 2 | 21 | 0 | 0 | 0 | 0 | 2010-04-16 21:15:00 | 2011-04-16 21:15:00 | 2010-04-16 21:16:29 | NULL | | 2 | 14 | 1 | 16 | 0 | 1 | 0 | 0 | 2010-04-19 12:07:03 | 2010-04-19 14:07:03 | 2010-04-19 12:07:03 | NULL | +----+---------+--------+-------------+-------+------------+------+---------+---------------------+---------------------+---------------------+--------------+ 2 rows in set (0.00 sec) mysql> select * from reservation; +----+-----------+------------+---------+-----------------+------------------+----------+---------------------+------+ | id | requestid | computerid | imageid | imagerevisionid | managementnodeid | remoteIP | lastcheck | pw | +----+-----------+------------+---------+-----------------+------------------+----------+---------------------+------+ | 1 | 1 | 1 | 8 | 8 | 1 | NULL | 0000-00-00 00:00:00 | NULL | | 2 | 2 | 2 | 10 | 10 | 1 | NULL | NULL | NULL | +----+-----------+------------+---------+-----------------+------------------+----------+---------------------+------+ 2 rows in set (0.00 sec) mysql> select * from vmprofile; +----+-------------------------------------------+----------+---------+----------+------------------------+------------------------+----------------+--------------------------------+-------------+----------+----------+ | id | profilename | vmtypeid | imageid | nasshare | datastorepath | vmpath | virtualswitch0 | virtualswitch1 | vmdisk | username | password | +----+-------------------------------------------+----------+---------+----------+------------------------+------------------------+----------------+--------------------------------+-------------+----------+----------+ | 1 | VMware GSX standard | 3 | 8 | NULL | /images/vmware | /images/vmware | VMnet1 | VMnet0 | localdisk | NULL | NULL | | 2 | Vmware ESX standard network mounted share | 5 | 9 | NULL | /vmfs/volumes/nfs1 | /vmfs/volumes/storage1 | VM Network | Virtual Machine Public Network | networkdisk | NULL | NULL | | 3 | Vmware ESX standard localdisk | 5 | 9 | NULL | /vmfs/volumes/storage1 | NULL | VM Network | Virtual Machine Public Network | localdisk | NULL | NULL | | 4 | Vmware ESX SAN | 5 | 9 | NULL | /vmfs/volumes/NetApp | /vmfs/volumes/storage1 | Intranet2 | MCNC Public | networkdisk | NULL | NULL | +----+-------------------------------------------+----------+---------+----------+------------------------+------------------------+----------------+--------------------------------+-------------+----------+----------+ 4 rows in set (0.00 sec) mysql> select * from resourcegroup; +----+--------------------+------------------+----------------+ | id | name | ownerusergroupid | resourcetypeid | +----+--------------------+------------------+----------------+ | 1 | allComputers | 3 | 12 | | 2 | allImages | 3 | 13 | | 3 | allManagementNodes | 3 | 16 | | 4 | allSchedules | 3 | 15 | | 8 | newimages | 4 | 12 | | 9 | newvmimages | 4 | 12 | | 10 | allVMimages | 4 | 13 | | 13 | allvmhosts | 3 | 12 | | 14 | allvmguests | 3 | 12 | +----+--------------------+------------------+----------------+ 9 rows in set (0.00 sec) mysql> select * from resourcemap; +------------------+-----------------+------------------+-----------------+ | resourcegroupid1 | resourcetypeid1 | resourcegroupid2 | resourcetypeid2 | +------------------+-----------------+------------------+-----------------+ | 2 | 13 | 1 | 12 | | 3 | 16 | 1 | 12 | | 3 | 16 | 8 | 12 | | 3 | 16 | 9 | 12 | | 3 | 16 | 13 | 12 | | 3 | 16 | 14 | 12 | | 10 | 13 | 14 | 12 | +------------------+-----------------+------------------+-----------------+ 7 rows in set (0.00 sec) === END mysql tables === Mark -- Mark Gardner --