[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
