Hi Ryan, you are great! I made quite a bit of progress with your suggestion.
I hope you can help me with this next step error: Seems like image creation was
successful but upon realod/poweron VMware perl toolkit looks for server '128'
instead of the full ip.
Something seems to be missing: Hope you can shed some more light on this!!!
2010-03-22 16:50:28|14912|vcld:main(165)|lastcheckin time updated for
management node 1: 2010-03-22 16:50:28
2010-03-22 16:50:33|14912|vcld:main(165)|lastcheckin time updated for
management node 1: 2010-03-22 16:50:33
===========================================================
OUTPUT for vcld run on 2010-03-22 16:51:04
===========================================================
2010-03-22 16:51:04|15551|vcld:main(116)|vcld environment variable set to 1 for
this process
2010-03-22 16:51:04|15551|utils.pm:rename_vcld_process(7901)|renamed process to
'vcld vcld'
2010-03-22 16:51:04|15551|utils.pm:get_management_node_info(6815)|management
node info retrieved from database for colbert
2010-03-22 16:51:04|15551|vcld:main(127)|retrieved management node information
from database
2010-03-22 16:51:04|15551|vcld:main(140)|management_node_id environment
variable set: 1
2010-03-22 16:51:04|15551|vcld:main(148)|management node checkin interval is 5
seconds
2010-03-22 16:51:04|15551|vcld:main(149)|vcld started on
colbert.vcls.priv.odu.edu
2010-03-22 16:51:09|15551|vcld:main(165)|lastcheckin time updated for
management node 1: 2010-03-22 16:51:09
2010-03-22
16:51:09|15551|2:2|image|utils.pm:reservation_being_processed(9634)|computerloadlog
'begin' entry does NOT exist for reservation 2
2010-03-22
16:51:09|15551|2:2|image|utils.pm:reservation_being_processed(9686)|reservation
is NOT currently being processed
2010-03-22 16:51:09|15551|2:2|image|vcld:main(276)|reservation 2 is NOT already
being processed
|15551|2:2|image| ---- WARNING ----
|15551|2:2|image| 2010-03-22
16:51:09|15551|2:2|image|utils.pm:get_request_info(5218)|preferredimageid is
not set for computer id=3
|15551|2:2|image| ( 0) utils.pm, notify (line: 737)
|15551|2:2|image| (-1) utils.pm, get_request_info (line: 5218)
|15551|2:2|image| (-2) vcld, main (line: 280)
2010-03-22 16:51:09|15551|2:2|image|utils.pm:get_request_info(5354)|standalone
affiliation found: Local
2010-03-22
16:51:09|15551|2:2|image|utils.pm:get_management_node_info(6815)|management
node info retrieved from database for colbert
2010-03-22 16:51:09|15551|2:2|image|vcld:main(281)|retrieved request
information from database
2010-03-22
16:51:09|15551|2:2|image|utils.pm:get_management_node_info(6815)|management
node info retrieved from database for colbert
2010-03-22
16:51:09|15551|2:2|image|DataStructure.pm:is_parent_reservation(854)|returning
true: parent reservation ID for this request: 2
2010-03-22 16:51:09|15551|2:2|image|utils.pm:update_request_state(2186)|request
2 state updated to: pending, laststate to: image
2010-03-22 16:51:09|15551|2:2|image|utils.pm:insertloadlog(4710)|inserted
computer=3, begin, beginning to process, state is image
2010-03-22 16:51:09|15551|2:2|image|vcld:make_new_child(509)|loaded VCL::image
module
2010-03-22 16:51:09|15553|2:2|image|vcld:make_new_child(582)|vcld environment
variable set to 0 for this process
2010-03-22 16:51:09|15553|2:2|image|Module.pm:new(132)|constructor called,
class=VCL::image
2010-03-22 16:51:09|15553|2:2|image|Module.pm:new(154)|VCL::image object created
2010-03-22 16:51:09|15551|2:2|image|vcld:make_new_child(566)|current number of
forked kids: 1
2010-03-22 16:51:09|15553|2:2|image|State.pm:initialize(85)|obtained a database
handle for this state process, stored as $ENV{dbh}
2010-03-22 16:51:09|15553|2:2|image|State.pm:check_image_os(839)|no corrections
need to be made to image OS: esx35
2010-03-22
16:51:09|15553|2:2|image|DataStructure.pm:is_parent_reservation(854)|returning
true: parent reservation ID for this request: 2
2010-03-22
16:51:09|15553|2:2|image|utils.pm:rename_vcld_process(7863)|reservation count: 1
2010-03-22
16:51:09|15553|2:2|image|utils.pm:rename_vcld_process(7882)|PARENTIMAGE: 1
2010-03-22
16:51:09|15553|2:2|image|utils.pm:rename_vcld_process(7883)|SUBIMAGE: 0
2010-03-22 16:51:09|15553|2:2|image|utils.pm:rename_vcld_process(7901)|renamed
process to 'vcld VCL::image 2:2 image imaging'
2010-03-22
16:51:09|15553|2:2|image|DataStructure.pm:is_parent_reservation(854)|returning
true: parent reservation ID for this request: 2
2010-03-22
16:51:09|15553|2:2|image|DataStructure.pm:is_parent_reservation(854)|returning
true: parent reservation ID for this request: 2
2010-03-22 16:51:09|15553|2:2|image|State.pm:initialize(121)|attempting to load
provisioning module: VCL::Module::Provisioning::esx
2010-03-22 16:51:09|15553|2:2|image|esx.pm:initialize(138)|esx vmware toolkit
root path found: /usr/lib/vmware-vcli/apps
2010-03-22 16:51:09|15553|2:2|image|esx.pm:initialize(140)|vmware ESX module
initialized
2010-03-22
16:51:09|15553|2:2|image|State.pm:initialize(127)|VCL::Module::Provisioning::esx
module loaded
2010-03-22 16:51:09|15553|2:2|image|Module.pm:new(132)|constructor called,
class=VCL::Module::Provisioning::esx
2010-03-22
16:51:09|15553|2:2|image|Module.pm:new(154)|VCL::Module::Provisioning::esx
object created
2010-03-22 16:51:09|15553|2:2|image|esx.pm:initialize(138)|esx vmware toolkit
root path found: /usr/lib/vmware-vcli/apps
2010-03-22 16:51:09|15553|2:2|image|esx.pm:initialize(140)|vmware ESX module
initialized
2010-03-22
16:51:09|15553|2:2|image|State.pm:initialize(131)|VCL::Module::Provisioning::esx
provisioner object created
2010-03-22 16:51:09|15553|2:2|image|State.pm:initialize(145)|attempting to load
OS module: VCL::Module::OS::Linux
2010-03-22
16:51:09|15553|2:2|image|State.pm:initialize(151)|VCL::Module::OS::Linux module
loaded
2010-03-22 16:51:09|15553|2:2|image|Module.pm:new(132)|constructor called,
class=VCL::Module::OS::Linux
2010-03-22 16:51:09|15553|2:2|image|Module.pm:new(154)|VCL::Module::OS::Linux
object created
2010-03-22
16:51:09|15553|2:2|image|State.pm:initialize(154)|VCL::Module::OS::Linux OS
object created
2010-03-22 16:51:09|15553|2:2|image|State.pm:initialize(169)|returning 1
2010-03-22 16:51:09|15553|2:2|image|vcld:make_new_child(591)|VCL::image object
created and initialized
No recipient addresses found in header
2010-03-22 16:51:09|15553|2:2|image|utils.pm:mail(1348)|SUCCESS -- Sending mail
To: , VCL IMAGE Creation Started: esx3-basewinxp-v0
2010-03-22 16:51:09|15553|2:2|image|utils.pm:run_ssh_command(6180)|executing
SSH command on 192.168.129.37:
|15553|2:2|image| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
192.168.129.37 'ls -1 /install/image/vmware_images/golden 2>&1' 2>&1
2010-03-22
16:51:09|15553|2:2|image|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|15553|2:2|image| none
2010-03-22 16:51:09|15553|2:2|image|utils.pm:run_ssh_command(6276)|SSH command
executed on 192.168.129.37, returning (0, "none")
|15553|2:2|image| ---- WARNING ----
|15553|2:2|image| 2010-03-22
16:51:09|15553|2:2|image|esx.pm:does_image_exist(930)|image
/install/image/vmware_images/golden/esx3-basewinxp-v0 does NOT exists
|15553|2:2|image| ( 0) utils.pm, notify (line: 737)
|15553|2:2|image| (-1) esx.pm, does_image_exist (line: 930)
|15553|2:2|image| (-2) image.pm, process (line: 135)
|15553|2:2|image| (-3) vcld, make_new_child (line: 594)
|15553|2:2|image| (-4) vcld, main (line: 341)
2010-03-22 16:51:09|15553|2:2|image|image.pm:process(145)|image
esx3-basewinxp-v0 does not exist in the repository
2010-03-22 16:51:09|15553|2:2|image|DataStructure.pm:_automethod(697)|data
structure updated: $self->request_data->{reservation}{2}{image}{lastupdate}
|15553|2:2|image| image_lastupdate = 2010-03-22 16:51:09
2010-03-22 16:51:09|15553|2:2|image|DataStructure.pm:_automethod(697)|data
structure updated:
$self->request_data->{reservation}{2}{imagerevision}{datecreated}
|15553|2:2|image| imagerevision_date_created = 2010-03-22 16:51:09
2010-03-22 16:51:09|15553|2:2|image|image.pm:process(161)|calling provisioning
module's capture() subroutine
2010-03-22
16:51:09|15553|2:2|image|esx.pm:capture(593)|**********************************************************
2010-03-22 16:51:09|15553|2:2|image|esx.pm:capture(594)|Entering ESX Capture
routine
2010-03-22 16:51:09|15553|2:2|image|utils.pm:run_ssh_command(6180)|executing
SSH command on 192.168.129.37:
|15553|2:2|image| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
192.168.129.37 'ls -1 /install/image/vmware_images/inuse/resxi000 2>&1' 2>&1
2010-03-22
16:51:09|15553|2:2|image|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|15553|2:2|image| esx3-basewinxp-v0.vmx
2010-03-22 16:51:09|15553|2:2|image|utils.pm:run_ssh_command(6276)|SSH command
executed on 192.168.129.37, returning (0, "esx3-basewinxp-v0.vmx")
Use of uninitialized value in concatenation (.) or string at
/usr/local/vcl/bin/../lib/VCL/Module/Provisioning/esx.pm line 646 (#1)
(W uninitialized) An undefined value was used as if it were already
defined. It was interpreted as a "" or a 0, but maybe it was a mistake.
To suppress this warning assign a defined value to your variables.
To help you figure out what was undefined, perl tells you what operation
you used the undefined value in. Note, however, that perl optimizes your
program and the operation displayed in the warning may not necessarily
appear literally in your program. For example, "that $foo" is
usually optimized into "that " . $foo, and the warning will refer to
the concatenation (.) operator, even though there is no . in your
program.
|15553|2:2|image| ---- WARNING ----
|15553|2:2|image| 2010-03-22
16:51:09|15553|2:2|image|vcld:warning_handler(636)|Use of uninitialized value
in concatenation (.) or string at
/usr/local/vcl/bin/../lib/VCL/Module/Provisioning/esx.pm line 646.
|15553|2:2|image| ( 0) utils.pm, notify (line: 737)
|15553|2:2|image| (-1) vcld, warning_handler (line: 636)
|15553|2:2|image| (-2) esx.pm, capture (line: 646)
|15553|2:2|image| (-3) image.pm, process (line: 162)
|15553|2:2|image| (-4) vcld, make_new_child (line: 594)
|15553|2:2|image| (-5) vcld, main (line: 341)
2010-03-22 16:51:09|15553|2:2|image|esx.pm:capture(646)|found previous name=
2010-03-22 16:51:09|15553|2:2|image|esx.pm:capture(648)|SSHing to node to
configure currentimage.txt
2010-03-22 16:51:09|15553|2:2|image|utils.pm:run_ssh_command(6180)|executing
SSH command on resxi000:
|15553|2:2|image| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x resxi000
'echo esx3-basewinxp-v0 > /root/currentimage.txt' 2>&1
2010-03-22
16:51:10|15553|2:2|image|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|15553|2:2|image| bash: /root/currentimage.txt: No such file or directory
2010-03-22 16:51:10|15553|2:2|image|utils.pm:run_ssh_command(6272)|SSH command
executed on resxi000, command:
|15553|2:2|image| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x resxi000
'echo esx3-basewinxp-v0 > /root/currentimage.txt' 2>&1
|15553|2:2|image| returning (1, "bash: /root/currentimage.txt: ...")
2010-03-22 16:51:10|15553|2:2|image|esx.pm:capture(658)|Power off command:
/usr/lib/vmware-vcli/apps/vm/vmcontrol.pl --server '128' --vmname resxi000
--operation poweroff --username 0 --password 'xxxxxxxxxxx'
Error connecting to server at 'https://128/sdk/webService': Perhaps host is not
a Virtual Center or ESX server
2010-03-22 16:51:10|15553|2:2|image|esx.pm:capture(661)|Powered off:
2010-03-22 16:51:10|15553|2:2|image|esx.pm:capture(663)|Waiting 5 seconds for
power off
2010-03-22 16:51:14|15551|vcld:main(165)|lastcheckin time updated for
management node 1: 2010-03-22 16:51:14
2010-03-22 16:51:15|15553|2:2|image|utils.pm:run_ssh_command(6180)|executing
SSH command on 192.168.129.37:
|15553|2:2|image| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
192.168.129.37 'mkdir /install/image/vmware_images/golden/esx3-basewinxp-v0'
2>&1
2010-03-22
16:51:15|15553|2:2|image|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|15553|2:2|image| none
2010-03-22 16:51:15|15553|2:2|image|utils.pm:run_ssh_command(6276)|SSH command
executed on 192.168.129.37, returning (0, "none")
|15553|2:2|image| ---- WARNING ----
|15553|2:2|image| 2010-03-22
16:51:15|15553|2:2|image|vcld:warning_handler(636)|Use of uninitialized value
in concatenation (.) or string at
/usr/local/vcl/bin/../lib/VCL/Module/Provisioning/esx.pm line 673.
|15553|2:2|image| ( 0) utils.pm, notify (line: 737)
|15553|2:2|image| (-1) vcld, warning_handler (line: 636)
|15553|2:2|image| (-2) esx.pm, capture (line: 673)
|15553|2:2|image| (-3) image.pm, process (line: 162)
|15553|2:2|image| (-4) vcld, make_new_child (line: 594)
|15553|2:2|image| (-5) vcld, main (line: 341)
2010-03-22 16:51:15|15553|2:2|image|utils.pm:run_ssh_command(6180)|executing
SSH command on 192.168.129.37:
|15553|2:2|image| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
192.168.129.37 'cp /install/image/vmware_images/inuse/resxi000/.vmdk
/install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0.vmdk'
2>&1
2010-03-22
16:51:15|15553|2:2|image|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|15553|2:2|image| cp: cannot stat
`/install/image/vmware_images/inuse/resxi000/.vmdk': No such file or directory
2010-03-22 16:51:15|15553|2:2|image|utils.pm:run_ssh_command(6272)|SSH command
executed on 192.168.129.37, command:
|15553|2:2|image| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
192.168.129.37 'cp /install/image/vmware_images/inuse/resxi000/.vmdk
/install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0.vmdk'
2>&1
|15553|2:2|image| returning (1, "cp: cannot stat `/install/imag...")
2010-03-22 16:51:15|15553|2:2|image|esx.pm:capture(679)|COPIED VMDK SUCCESSFULLY
|15553|2:2|image| ---- WARNING ----
|15553|2:2|image| 2010-03-22
16:51:15|15553|2:2|image|vcld:warning_handler(636)|Use of uninitialized value
in concatenation (.) or string at
/usr/local/vcl/bin/../lib/VCL/Module/Provisioning/esx.pm line 682.
|15553|2:2|image| ( 0) utils.pm, notify (line: 737)
|15553|2:2|image| (-1) vcld, warning_handler (line: 636)
|15553|2:2|image| (-2) esx.pm, capture (line: 682)
|15553|2:2|image| (-3) image.pm, process (line: 162)
|15553|2:2|image| (-4) vcld, make_new_child (line: 594)
|15553|2:2|image| (-5) vcld, main (line: 341)
2010-03-22 16:51:15|15553|2:2|image|utils.pm:run_ssh_command(6180)|executing
SSH command on 192.168.129.37:
|15553|2:2|image| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
192.168.129.37 'cp /install/image/vmware_images/inuse/resxi000/.vmx
/install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0.vmx'
2>&1
2010-03-22
16:51:15|15553|2:2|image|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|15553|2:2|image| cp: cannot stat
`/install/image/vmware_images/inuse/resxi000/.vmx': No such file or directory
2010-03-22 16:51:15|15553|2:2|image|utils.pm:run_ssh_command(6272)|SSH command
executed on 192.168.129.37, command:
|15553|2:2|image| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
192.168.129.37 'cp /install/image/vmware_images/inuse/resxi000/.vmx
/install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0.vmx'
2>&1
|15553|2:2|image| returning (1, "cp: cannot stat `/install/imag...")
2010-03-22 16:51:15|15553|2:2|image|esx.pm:capture(688)|COPIED VMX SUCCESSFULLY
2010-03-22 16:51:15|15553|2:2|image|esx.pm:capture(691)|Rewriting VMDK and VMX
files with new image name
|15553|2:2|image| ---- WARNING ----
|15553|2:2|image| 2010-03-22
16:51:15|15553|2:2|image|vcld:warning_handler(636)|Use of uninitialized value
in concatenation (.) or string at
/usr/local/vcl/bin/../lib/VCL/Module/Provisioning/esx.pm line 692.
|15553|2:2|image| ( 0) utils.pm, notify (line: 737)
|15553|2:2|image| (-1) vcld, warning_handler (line: 636)
|15553|2:2|image| (-2) esx.pm, capture (line: 692)
|15553|2:2|image| (-3) image.pm, process (line: 162)
|15553|2:2|image| (-4) vcld, make_new_child (line: 594)
|15553|2:2|image| (-5) vcld, main (line: 341)
2010-03-22 16:51:15|15553|2:2|image|utils.pm:run_ssh_command(6180)|executing
SSH command on 192.168.129.37:
|15553|2:2|image| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
192.168.129.37 'sed -i "s//esx3-basewinxp-v0/"
/install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0.vmx'
2>&1
2010-03-22
16:51:15|15553|2:2|image|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|15553|2:2|image| sed: can't read
/install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0.vmx: No
such file or directory
2010-03-22 16:51:15|15553|2:2|image|utils.pm:run_ssh_command(6272)|SSH command
executed on 192.168.129.37, command:
|15553|2:2|image| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
192.168.129.37 'sed -i "s//esx3-basewinxp-v0/"
/install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0.vmx'
2>&1
|15553|2:2|image| returning (2, "sed: can't read /install/image...")
|15553|2:2|image| ---- WARNING ----
|15553|2:2|image| 2010-03-22
16:51:15|15553|2:2|image|vcld:warning_handler(636)|Use of uninitialized value
in concatenation (.) or string at
/usr/local/vcl/bin/../lib/VCL/Module/Provisioning/esx.pm line 696.
|15553|2:2|image| ( 0) utils.pm, notify (line: 737)
|15553|2:2|image| (-1) vcld, warning_handler (line: 636)
|15553|2:2|image| (-2) esx.pm, capture (line: 696)
|15553|2:2|image| (-3) image.pm, process (line: 162)
|15553|2:2|image| (-4) vcld, make_new_child (line: 594)
|15553|2:2|image| (-5) vcld, main (line: 341)
2010-03-22 16:51:15|15553|2:2|image|utils.pm:run_ssh_command(6180)|executing
SSH command on 192.168.129.37:
|15553|2:2|image| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
192.168.129.37 'sed -i "s//esx3-basewinxp-v0/"
/install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0.vmdk'
2>&1
2010-03-22
16:51:15|15553|2:2|image|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|15553|2:2|image| sed: can't read
/install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0.vmdk:
No such file or directory
2010-03-22 16:51:15|15553|2:2|image|utils.pm:run_ssh_command(6272)|SSH command
executed on 192.168.129.37, command:
|15553|2:2|image| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
192.168.129.37 'sed -i "s//esx3-basewinxp-v0/"
/install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0.vmdk'
2>&1
|15553|2:2|image| returning (2, "sed: can't read /install/image...")
|15553|2:2|image| ---- WARNING ----
|15553|2:2|image| 2010-03-22
16:51:15|15553|2:2|image|vcld:warning_handler(636)|Use of uninitialized value
in concatenation (.) or string at
/usr/local/vcl/bin/../lib/VCL/Module/Provisioning/esx.pm line 703.
|15553|2:2|image| ( 0) utils.pm, notify (line: 737)
|15553|2:2|image| (-1) vcld, warning_handler (line: 636)
|15553|2:2|image| (-2) esx.pm, capture (line: 703)
|15553|2:2|image| (-3) image.pm, process (line: 162)
|15553|2:2|image| (-4) vcld, make_new_child (line: 594)
|15553|2:2|image| (-5) vcld, main (line: 341)
2010-03-22 16:51:15|15553|2:2|image|esx.pm:capture(705)|Preparing to ssh to
192.168.129.37 copy vmdk-flat from
/install/image/vmware_images/inuse/resxi000/-flat.vmdk to
/install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0-flat.vmdk
2010-03-22 16:51:15|15553|2:2|image|esx.pm:capture(706)|SSHing to copy
vmdk-flat file
2010-03-22 16:51:15|15553|2:2|image|utils.pm:run_ssh_command(6180)|executing
SSH command on 192.168.129.37:
|15553|2:2|image| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
192.168.129.37 'cp /install/image/vmware_images/inuse/resxi000/-flat.vmdk
/install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0-flat.vmdk'
2>&1
2010-03-22
16:51:16|15553|2:2|image|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|15553|2:2|image| cp: cannot stat
`/install/image/vmware_images/inuse/resxi000/-flat.vmdk': No such file or
directory
2010-03-22 16:51:16|15553|2:2|image|utils.pm:run_ssh_command(6272)|SSH command
executed on 192.168.129.37, command:
|15553|2:2|image| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
192.168.129.37 'cp /install/image/vmware_images/inuse/resxi000/-flat.vmdk
/install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0-flat.vmdk'
2>&1
|15553|2:2|image| returning (1, "cp: cannot stat `/install/imag...")
2010-03-22 16:51:16|15553|2:2|image|image.pm:process(162)|esx3-basewinxp-v0
image was successfully captured by the provisioning module
2010-03-22 16:51:16|15553|2:2|image|image.pm:process(219)|esx3-basewinxp-v0
image files successfully saved
2010-03-22 16:51:16|15553|2:2|image|utils.pm:update_request_state(2186)|request
2 state updated to: completed, laststate to: image
2010-03-22 16:51:16|15553|2:2|image|image.pm:process(222)|request state updated
to completed, laststate to image
2010-03-22 16:51:16|15553|2:2|image|esx.pm:get_image_size(960)|getting size of
image: esx3-basewinxp-v0
2010-03-22 16:51:16|15553|2:2|image|utils.pm:run_ssh_command(6180)|executing
SSH command on 192.168.129.37:
|15553|2:2|image| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
192.168.129.37 '/bin/ls -s1
/install/image/vmware_images/golden/esx3-basewinxp-v0 2>&1' 2>&1
2010-03-22
16:51:16|15553|2:2|image|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|15553|2:2|image| total 0
2010-03-22 16:51:16|15553|2:2|image|utils.pm:run_ssh_command(6276)|SSH command
executed on 192.168.129.37, returning (0, "total 0")
|15553|2:2|image| ---- WARNING ----
|15553|2:2|image| 2010-03-22
16:51:16|15553|2:2|image|image.pm:process(235)|unable to retrieve size of new
revision: esx3-basewinxp-v0, old size will be used
|15553|2:2|image| ( 0) utils.pm, notify (line: 737)
|15553|2:2|image| (-1) image.pm, process (line: 235)
|15553|2:2|image| (-2) vcld, make_new_child (line: 594)
|15553|2:2|image| (-3) vcld, main (line: 341)
2010-03-22 16:51:16|15553|2:2|image|DataStructure.pm:_automethod(697)|data
structure updated: $self->request_data->{reservation}{2}{image}{size}
|15553|2:2|image| image_size = 1450
2010-03-22 16:51:16|15553|2:2|image|image.pm:process(260)|image and
imagerevision tables updated for image=10, imagerevision=11,
name=esx3-basewinxp-v0, lastupdate=2010-03-22 16:51:09, deleted=0, size=1450
2010-03-22 16:51:16|15553|2:2|image|utils.pm:mail(1348)|SUCCESS -- Sending mail
To: r...@localhost, VCL -- No Apps (ESXi WinXP) Image Creation Succeeded
No recipient addresses found in header
2010-03-22 16:51:16|15553|2:2|image|utils.pm:mail(1348)|SUCCESS -- Sending mail
To: , VCL IMAGE Creation Completed: esx3-basewinxp-v0
2010-03-22 16:51:16|15553|2:2|image|utils.pm:insertloadlog(4710)|inserted
computer=3, loadimagevmware, VCL::utils::insert_reload_request: switching
request state to reload
2010-03-22
16:51:16|15553|2:2|image|utils.pm:update_computer_state(2228)|computer 3 state
updated to: reload
2010-03-22 16:51:16|15553|2:2|image|utils.pm:insert_reload_request(9117)|req=2:
setting computerid 3 into reload state
2010-03-22 16:51:16|15553|2:2|image|utils.pm:insert_request(9020)|inserted new
reload request into request table, request id=3
2010-03-22 16:51:16|15553|2:2|image|utils.pm:insert_request(9051)|inserted new
reload request into reservation table, reservation id=3
2010-03-22 16:51:16|15553|2:2|image|utils.pm:insert_reload_request(9127)|req=2:
inserted new reload request, id=3 nodeid=3, imageid=10, imagerevision_id=11
2010-03-22 16:51:16|15553|2:2|image|utils.pm:insertloadlog(4710)|inserted
computer=3, info, VCL::utils::insert_reload_request: created new reload request
2010-03-22
16:51:16|15553|2:2|image|image.pm:reservation_successful(348)|inserted reload
request into database for computer id=3
2010-03-22 16:51:16|15553|2:2|image|utils.pm:switch_state(8018)|called from
VCL::image::reservation_successful(351)
2010-03-22 16:51:16|15553|2:2|image|utils.pm:switch_state(8054)|parent: parent
reservation ID for this request: 2
2010-03-22 16:51:16|15553|2:2|image|utils.pm:insertloadlog(4710)|inserted
computer=3, info, VCL::image: switching request state to complete
2010-03-22 16:51:16|15553|2:2|image|utils.pm:update_request_state(2186)|request
2 state updated to: complete, laststate to: image
2010-03-22 16:51:16|15553|2:2|image|utils.pm:switch_state(8078)|req=2: request
state changed: image->complete, laststate: image->image
2010-03-22 16:51:16|15553|2:2|image|utils.pm:insertloadlog(4710)|inserted
computer=3, info, VCL::image: request state changed to complete, laststate to
image
2010-03-22 16:51:16|15553|2:2|image|utils.pm:switch_state(8088)|req=2: computer
state not specified, resxi000 state not changed
2010-03-22 16:51:16|15553|2:2|image|utils.pm:switch_state(8106)|req=2: log
table id=0, ending set to EOR
2010-03-22 16:51:16|15553|2:2|image|utils.pm:insertloadlog(4710)|inserted
computer=3, info, VCL::image: process exiting
2010-03-22 16:51:16|15553|2:2|image|utils.pm:switch_state(8122)|req=2: process
exiting
2010-03-22 16:51:16|15553|2:2|image|State.pm:DESTROY(905)|destructor called,
ref($self)=VCL::image
2010-03-22
16:51:16|15553|2:2|image|utils.pm:delete_computerloadlog_reservation(7551)|removing
computerloadlog entries matching loadstate = begin
2010-03-22
16:51:16|15553|2:2|image|utils.pm:delete_computerloadlog_reservation(7598)|deleted
rows from computerloadlog for reservation id=2
2010-03-22 16:51:16|15553|2:2|image|State.pm:DESTROY(912)|removed
computerloadlog rows with loadstate=begin for reservation
2010-03-22 16:51:16|15553|2:2|image|State.pm:DESTROY(924)|number of database
handles state process created: 1
2010-03-22 16:51:16|15553|2:2|image|State.pm:DESTROY(933)|process has a
database handle stored in $ENV{dbh}, attempting disconnect
2010-03-22 16:51:16|15553|2:2|image|State.pm:DESTROY(935)|$ENV{dbh}: database
disconnect successful
2010-03-22 16:51:16|15553|2:2|image|State.pm:DESTROY(949)|VCL::image process
15553 exiting
2010-03-22 16:51:16|15551|vcld:REAPER(744)|VCL process exited for reservation 2
2010-03-22 16:51:16|15551|vcld:main(165)|lastcheckin time updated for
management node 1: 2010-03-22 16:51:16
2010-03-22
16:51:16|15551|3:3|reload|utils.pm:reservation_being_processed(9634)|computerloadlog
'begin' entry does NOT exist for reservation 3
2010-03-22
16:51:16|15551|3:3|reload|utils.pm:reservation_being_processed(9686)|reservation
is NOT currently being processed
2010-03-22 16:51:16|15551|3:3|reload|vcld:main(276)|reservation 3 is NOT
already being processed
|15551|3:3|reload| ---- WARNING ----
|15551|3:3|reload| 2010-03-22
16:51:16|15551|3:3|reload|utils.pm:get_request_info(5218)|preferredimageid is
not set for computer id=3
|15551|3:3|reload| ( 0) utils.pm, notify (line: 737)
|15551|3:3|reload| (-1) utils.pm, get_request_info (line: 5218)
|15551|3:3|reload| (-2) vcld, main (line: 280)
2010-03-22 16:51:16|15551|3:3|reload|utils.pm:get_request_info(5354)|standalone
affiliation found: Local
2010-03-22
16:51:16|15551|3:3|reload|utils.pm:get_management_node_info(6815)|management
node info retrieved from database for colbert
2010-03-22 16:51:16|15551|3:3|reload|vcld:main(281)|retrieved request
information from database
2010-03-22
16:51:16|15551|3:3|reload|DataStructure.pm:is_parent_reservation(854)|returning
true: parent reservation ID for this request: 3
2010-03-22
16:51:16|15551|3:3|reload|utils.pm:update_request_state(2186)|request 3 state
updated to: pending, laststate to: reload
2010-03-22 16:51:16|15551|3:3|reload|utils.pm:insertloadlog(4710)|inserted
computer=3, begin, beginning to process, state is reload
2010-03-22 16:51:16|15551|3:3|reload|vcld:make_new_child(501)|request will be
processed by new.pm
2010-03-22 16:51:16|15551|3:3|reload|vcld:make_new_child(509)|loaded VCL::new
module
2010-03-22 16:51:16|15755|3:3|reload|vcld:make_new_child(582)|vcld environment
variable set to 0 for this process
2010-03-22 16:51:16|15755|3:3|reload|Module.pm:new(132)|constructor called,
class=VCL::new
2010-03-22 16:51:16|15551|3:3|reload|vcld:make_new_child(566)|current number of
forked kids: 1
2010-03-22 16:51:16|15755|3:3|reload|Module.pm:new(154)|VCL::new object created
2010-03-22 16:51:16|15755|3:3|reload|State.pm:initialize(85)|obtained a
database handle for this state process, stored as $ENV{dbh}
2010-03-22 16:51:16|15755|3:3|reload|State.pm:check_image_os(820)|no
corrections need to be made, not an imaging request, returning 1
2010-03-22
16:51:16|15755|3:3|reload|DataStructure.pm:is_parent_reservation(854)|returning
true: parent reservation ID for this request: 3
2010-03-22
16:51:16|15755|3:3|reload|utils.pm:rename_vcld_process(7863)|reservation count:
1
2010-03-22
16:51:16|15755|3:3|reload|utils.pm:rename_vcld_process(7882)|PARENTIMAGE: 1
2010-03-22
16:51:16|15755|3:3|reload|utils.pm:rename_vcld_process(7883)|SUBIMAGE: 0
2010-03-22 16:51:16|15755|3:3|reload|utils.pm:rename_vcld_process(7901)|renamed
process to 'vcld VCL::new 3:3 reload'
2010-03-22
16:51:16|15755|3:3|reload|DataStructure.pm:is_parent_reservation(854)|returning
true: parent reservation ID for this request: 3
2010-03-22
16:51:16|15755|3:3|reload|DataStructure.pm:is_parent_reservation(854)|returning
true: parent reservation ID for this request: 3
2010-03-22 16:51:16|15755|3:3|reload|State.pm:initialize(121)|attempting to
load provisioning module: VCL::Module::Provisioning::esx
2010-03-22 16:51:16|15551|2:2|complete|vcld:main(250)|request deleted
2010-03-22 16:51:16|15755|3:3|reload|esx.pm:initialize(138)|esx vmware toolkit
root path found: /usr/lib/vmware-vcli/apps
2010-03-22 16:51:16|15755|3:3|reload|esx.pm:initialize(140)|vmware ESX module
initialized
2010-03-22
16:51:16|15755|3:3|reload|State.pm:initialize(127)|VCL::Module::Provisioning::esx
module loaded
2010-03-22 16:51:16|15755|3:3|reload|Module.pm:new(132)|constructor called,
class=VCL::Module::Provisioning::esx
2010-03-22
16:51:16|15755|3:3|reload|Module.pm:new(154)|VCL::Module::Provisioning::esx
object created
2010-03-22 16:51:16|15755|3:3|reload|esx.pm:initialize(138)|esx vmware toolkit
root path found: /usr/lib/vmware-vcli/apps
2010-03-22 16:51:16|15755|3:3|reload|esx.pm:initialize(140)|vmware ESX module
initialized
2010-03-22
16:51:16|15755|3:3|reload|State.pm:initialize(131)|VCL::Module::Provisioning::esx
provisioner object created
2010-03-22 16:51:16|15755|3:3|reload|State.pm:initialize(145)|attempting to
load OS module: VCL::Module::OS::Linux
2010-03-22
16:51:16|15755|3:3|reload|State.pm:initialize(151)|VCL::Module::OS::Linux
module loaded
2010-03-22 16:51:16|15755|3:3|reload|Module.pm:new(132)|constructor called,
class=VCL::Module::OS::Linux
2010-03-22 16:51:16|15755|3:3|reload|Module.pm:new(154)|VCL::Module::OS::Linux
object created
2010-03-22
16:51:16|15755|3:3|reload|State.pm:initialize(154)|VCL::Module::OS::Linux OS
object created
2010-03-22 16:51:16|15755|3:3|reload|State.pm:initialize(169)|returning 1
2010-03-22 16:51:16|15755|3:3|reload|vcld:make_new_child(591)|VCL::new object
created and initialized
2010-03-22
16:51:16|15755|3:3|reload|DataStructure.pm:is_parent_reservation(854)|returning
true: parent reservation ID for this request: 3
2010-03-22
16:51:16|15755|3:3|reload|DataStructure.pm:get_computer_state_name(1946)|attempting
to retrieve current state of computer resxi000 from the database
2010-03-22
16:51:16|15755|3:3|reload|DataStructure.pm:get_computer_state_name(1977)|retrieved
current state of computer resxi000 from the database: reload
2010-03-22 16:51:16|15755|3:3|reload|DataStructure.pm:_automethod(697)|data
structure updated: $self->request_data->{reservation}{3}{computer}{state}{name}
|15755|3:3|reload| computer_state_name = reload
|15755|3:3|reload| ---- WARNING ----
|15755|3:3|reload| 2010-03-22
16:51:16|15755|3:3|reload|DataStructure.pm:_automethod(675)|corresponding data
has not been initialized for get_computer_preferredimage_id:
$self->request_data->{reservation}{3}{computer}{preferredimage}{id}
|15755|3:3|reload| ( 0) utils.pm, notify (line: 737)
|15755|3:3|reload| (-1) DataStructure.pm, _automethod (line: 675)
|15755|3:3|reload| (-2) Autoload.pm, __ANON__ (line: 80)
|15755|3:3|reload| (-3) new.pm, process (line: 106)
|15755|3:3|reload| (-4) vcld, make_new_child (line: 594)
|15755|3:3|reload| (-5) vcld, main (line: 341)
|15755|3:3|reload| ---- WARNING ----
|15755|3:3|reload| 2010-03-22
16:51:16|15755|3:3|reload|DataStructure.pm:_automethod(675)|corresponding data
has not been initialized for get_computer_preferredimage_name:
$self->request_data->{reservation}{3}{computer}{preferredimage}{name}
|15755|3:3|reload| ( 0) utils.pm, notify (line: 737)
|15755|3:3|reload| (-1) DataStructure.pm, _automethod (line: 675)
|15755|3:3|reload| (-2) Autoload.pm, __ANON__ (line: 80)
|15755|3:3|reload| (-3) new.pm, process (line: 107)
|15755|3:3|reload| (-4) vcld, make_new_child (line: 594)
|15755|3:3|reload| (-5) vcld, main (line: 341)
2010-03-22
16:51:16|15755|3:3|reload|utils.pm:get_management_node_id(9364)|environment
variable: 1
2010-03-22 16:51:16|15755|3:3|reload|new.pm:process(134)|reservation is parent
= 1
2010-03-22 16:51:16|15755|3:3|reload|new.pm:process(135)|preload only = 0
2010-03-22 16:51:16|15755|3:3|reload|new.pm:process(136)|originating request
state = reload
2010-03-22 16:51:16|15755|3:3|reload|new.pm:process(137)|originating request
laststate = image
2010-03-22 16:51:16|15755|3:3|reload|new.pm:process(138)|originating computer
state = reload
2010-03-22 16:51:16|15755|3:3|reload|new.pm:process(139)|originating computer
type = virtualmachine
2010-03-22
16:51:16|15755|3:3|reload|DataStructure.pm:is_parent_reservation(854)|returning
true: parent reservation ID for this request: 3
2010-03-22
16:51:16|15755|3:3|reload|DataStructure.pm:get_computer_state_name(1946)|attempting
to retrieve current state of computer resxi000 from the database
2010-03-22
16:51:16|15755|3:3|reload|DataStructure.pm:get_computer_state_name(1977)|retrieved
current state of computer resxi000 from the database: reload
2010-03-22 16:51:16|15755|3:3|reload|DataStructure.pm:_automethod(697)|data
structure updated: $self->request_data->{reservation}{3}{computer}{state}{name}
|15755|3:3|reload| computer_state_name = reload
|15755|3:3|reload| ---- WARNING ----
|15755|3:3|reload| 2010-03-22
16:51:16|15755|3:3|reload|DataStructure.pm:_automethod(675)|corresponding data
has not been initialized for get_computer_preferredimage_id:
$self->request_data->{reservation}{3}{computer}{preferredimage}{id}
|15755|3:3|reload| ( 0) utils.pm, notify (line: 737)
|15755|3:3|reload| (-1) DataStructure.pm, _automethod (line: 675)
|15755|3:3|reload| (-2) Autoload.pm, __ANON__ (line: 80)
|15755|3:3|reload| (-3) new.pm, computer_not_being_used (line: 750)
|15755|3:3|reload| (-4) new.pm, process (line: 170)
|15755|3:3|reload| (-5) vcld, make_new_child (line: 594)
|15755|3:3|reload| (-6) vcld, main (line: 341)
|15755|3:3|reload| ---- WARNING ----
|15755|3:3|reload| 2010-03-22
16:51:16|15755|3:3|reload|DataStructure.pm:_automethod(675)|corresponding data
has not been initialized for get_computer_preferredimage_name:
$self->request_data->{reservation}{3}{computer}{preferredimage}{name}
|15755|3:3|reload| ( 0) utils.pm, notify (line: 737)
|15755|3:3|reload| (-1) DataStructure.pm, _automethod (line: 675)
|15755|3:3|reload| (-2) Autoload.pm, __ANON__ (line: 80)
|15755|3:3|reload| (-3) new.pm, computer_not_being_used (line: 751)
|15755|3:3|reload| (-4) new.pm, process (line: 170)
|15755|3:3|reload| (-5) vcld, make_new_child (line: 594)
|15755|3:3|reload| (-6) vcld, main (line: 341)
2010-03-22
16:51:16|15755|3:3|reload|utils.pm:get_management_node_id(9364)|environment
variable: 1
2010-03-22
16:51:16|15755|3:3|reload|new.pm:computer_not_being_used(788)|resxi000 state is
reload
2010-03-22
16:51:16|15755|3:3|reload|new.pm:computer_not_being_used(798)|resxi000 is
available, its state is reload
2010-03-22 16:51:16|15755|3:3|reload|new.pm:process(170)|resxi000 is not being
used
2010-03-22
16:51:16|15755|3:3|reload|DataStructure.pm:is_parent_reservation(854)|returning
true: parent reservation ID for this request: 3
2010-03-22
16:51:16|15755|3:3|reload|DataStructure.pm:get_computer_state_name(1946)|attempting
to retrieve current state of computer resxi000 from the database
2010-03-22
16:51:16|15755|3:3|reload|DataStructure.pm:get_computer_state_name(1977)|retrieved
current state of computer resxi000 from the database: reload
2010-03-22 16:51:16|15755|3:3|reload|DataStructure.pm:_automethod(697)|data
structure updated: $self->request_data->{reservation}{3}{computer}{state}{name}
|15755|3:3|reload| computer_state_name = reload
|15755|3:3|reload| ---- WARNING ----
|15755|3:3|reload| 2010-03-22
16:51:16|15755|3:3|reload|DataStructure.pm:_automethod(675)|corresponding data
has not been initialized for get_computer_preferredimage_id:
$self->request_data->{reservation}{3}{computer}{preferredimage}{id}
|15755|3:3|reload| ( 0) utils.pm, notify (line: 737)
|15755|3:3|reload| (-1) DataStructure.pm, _automethod (line: 675)
|15755|3:3|reload| (-2) Autoload.pm, __ANON__ (line: 80)
|15755|3:3|reload| (-3) new.pm, reload_image (line: 480)
|15755|3:3|reload| (-4) new.pm, process (line: 266)
|15755|3:3|reload| (-5) vcld, make_new_child (line: 594)
|15755|3:3|reload| (-6) vcld, main (line: 341)
|15755|3:3|reload| ---- WARNING ----
|15755|3:3|reload| 2010-03-22
16:51:16|15755|3:3|reload|DataStructure.pm:_automethod(675)|corresponding data
has not been initialized for get_computer_preferredimage_name:
$self->request_data->{reservation}{3}{computer}{preferredimage}{name}
|15755|3:3|reload| ( 0) utils.pm, notify (line: 737)
|15755|3:3|reload| (-1) DataStructure.pm, _automethod (line: 675)
|15755|3:3|reload| (-2) Autoload.pm, __ANON__ (line: 80)
|15755|3:3|reload| (-3) new.pm, reload_image (line: 481)
|15755|3:3|reload| (-4) new.pm, process (line: 266)
|15755|3:3|reload| (-5) vcld, make_new_child (line: 594)
|15755|3:3|reload| (-6) vcld, main (line: 341)
2010-03-22
16:51:16|15755|3:3|reload|utils.pm:get_management_node_id(9364)|environment
variable: 1
2010-03-22 16:51:16|15755|3:3|reload|new.pm:reload_image(514)|calling
VCL::Module::Provisioning::esx->node_status()
2010-03-22 16:51:16|15755|3:3|reload|utils.pm:insertloadlog(4710)|inserted
computer=3, statuscheck, checking status of node
2010-03-22 16:51:16|15755|3:3|reload|esx.pm:node_status(787)|Entering
node_status, checking status of resxi000
2010-03-22
16:51:16|15755|3:3|reload|esx.pm:node_status(788)|request_for_imaging: 0
2010-03-22 16:51:16|15755|3:3|reload|esx.pm:node_status(789)|requeseted image
name: esx3-basewinxp-v0
2010-03-22 16:51:16|15755|3:3|reload|esx.pm:node_status(819)|checking if
resxi000 is pingable
2010-03-22 16:51:16|15755|3:3|reload|esx.pm:node_status(822)|resxi000 is
pingable (1)
2010-03-22 16:51:16|15755|3:3|reload|esx.pm:node_status(836)|Trying to ssh...
2010-03-22 16:51:17|15755|3:3|reload|esx.pm:node_status(874)|status set to
RELOAD
2010-03-22 16:51:17|15755|3:3|reload|esx.pm:node_status(882)|returning node
status hash reference ($node_status->{status}=RELOAD)
2010-03-22 16:51:17|15755|3:3|reload|new.pm:reload_image(529)|node_status
returned a hash reference
2010-03-22 16:51:17|15755|3:3|reload|new.pm:reload_image(534)|node_status hash
reference contains key {status}=RELOAD
2010-03-22 16:51:17|15755|3:3|reload|new.pm:reload_image(576)|request state is
reload, node will be reloaded regardless of status
2010-03-22 16:51:17|15755|3:3|reload|new.pm:reload_image(602)|node status is
reload, resxi000 will be reloaded
2010-03-22 16:51:17|15755|3:3|reload|utils.pm:insertloadlog(4710)|inserted
computer=3, loadimageblade, resxi000 must be reloaded with esx3-basewinxp-v0
2010-03-22 16:51:17|15755|3:3|reload|new.pm:reload_image(616)|calling
VCL::Module::Provisioning::esx->does_image_exist()
2010-03-22 16:51:17|15755|3:3|reload|utils.pm:run_ssh_command(6180)|executing
SSH command on 192.168.129.37:
|15755|3:3|reload| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
192.168.129.37 'ls -1 /install/image/vmware_images/golden 2>&1' 2>&1
2010-03-22
16:51:17|15755|3:3|reload|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|15755|3:3|reload| esx3-basewinxp-v0
2010-03-22 16:51:17|15755|3:3|reload|utils.pm:run_ssh_command(6276)|SSH command
executed on 192.168.129.37, returning (0, "esx3-basewinxp-v0")
2010-03-22 16:51:17|15755|3:3|reload|esx.pm:does_image_exist(917)|image
esx3-basewinxp-v0 exists
2010-03-22 16:51:17|15755|3:3|reload|new.pm:reload_image(619)|esx3-basewinxp-v0
exists on this management node
2010-03-22 16:51:17|15755|3:3|reload|utils.pm:insertloadlog(4710)|inserted
computer=3, doesimageexists, confirmed image exists
2010-03-22
16:51:17|15755|3:3|reload|utils.pm:update_computer_state(2228)|computer 3 state
updated to: reloading
2010-03-22 16:51:17|15755|3:3|reload|new.pm:reload_image(652)|computer resxi000
state set to reloading
2010-03-22 16:51:17|15755|3:3|reload|utils.pm:insertloadlog(4710)|inserted
computer=3, info, computer state updated to reloading
2010-03-22 16:51:17|15755|3:3|reload|new.pm:reload_image(663)|calling
VCL::Module::Provisioning::esx->load() subroutine
2010-03-22 16:51:17|15755|3:3|reload|utils.pm:insertloadlog(4710)|inserted
computer=3, info, calling VCL::Module::Provisioning::esx->load() subroutine
2010-03-22
16:51:17|15755|3:3|reload|esx.pm:load(165)|****************************************************
|15755|3:3|reload| ---- WARNING ----
|15755|3:3|reload| 2010-03-22
16:51:17|15755|3:3|reload|DataStructure.pm:_automethod(675)|corresponding data
has not been initialized for get_computer_eth0_mac_address:
$self->request_data->{reservation}{3}{computer}{eth0macaddress}
|15755|3:3|reload| ( 0) utils.pm, notify (line: 737)
|15755|3:3|reload| (-1) DataStructure.pm, _automethod (line: 675)
|15755|3:3|reload| (-2) Autoload.pm, __ANON__ (line: 80)
|15755|3:3|reload| (-3) esx.pm, load (line: 181)
|15755|3:3|reload| (-4) new.pm, reload_image (line: 665)
|15755|3:3|reload| (-5) new.pm, process (line: 266)
|15755|3:3|reload| (-6) vcld, make_new_child (line: 594)
|15755|3:3|reload| ---- WARNING ----
|15755|3:3|reload| 2010-03-22
16:51:17|15755|3:3|reload|DataStructure.pm:_automethod(675)|corresponding data
has not been initialized for get_computer_eth1_mac_address:
$self->request_data->{reservation}{3}{computer}{eth1macaddress}
|15755|3:3|reload| ( 0) utils.pm, notify (line: 737)
|15755|3:3|reload| (-1) DataStructure.pm, _automethod (line: 675)
|15755|3:3|reload| (-2) Autoload.pm, __ANON__ (line: 80)
|15755|3:3|reload| (-3) esx.pm, load (line: 182)
|15755|3:3|reload| (-4) new.pm, reload_image (line: 665)
|15755|3:3|reload| (-5) new.pm, process (line: 266)
|15755|3:3|reload| (-6) vcld, make_new_child (line: 594)
2010-03-22 16:51:17|15755|3:3|reload|esx.pm:load(193)|Calling
get_vmware_host_info
sh: -c: line 0: syntax error near unexpected token `)'
sh: -c: line 0: `/usr/lib/vmware-vcli/apps/host/hostinfo.pl --username 0
--password xxxxxxxxxxx --server 128 --fields hostname'
2010-03-22 16:51:17|15755|3:3|reload|esx.pm:get_vmware_host_info(1018)|host
info output for 128
|15755|3:3|reload| ---- WARNING ----
|15755|3:3|reload| 2010-03-22
16:51:17|15755|3:3|reload|esx.pm:get_vmware_host_info(1029)|no value found for
hostname output=
|15755|3:3|reload| ( 0) utils.pm, notify (line: 737)
|15755|3:3|reload| (-1) esx.pm, get_vmware_host_info (line: 1029)
|15755|3:3|reload| (-2) esx.pm, load (line: 194)
|15755|3:3|reload| (-3) new.pm, reload_image (line: 665)
|15755|3:3|reload| (-4) new.pm, process (line: 266)
|15755|3:3|reload| (-5) vcld, make_new_child (line: 594)
|15755|3:3|reload| (-6) vcld, main (line: 341)
2010-03-22 16:51:17|15755|3:3|reload|esx.pm:load(201)|Unable to collect
hostname_value for vmware host name using hostname from database
2010-03-22 16:51:17|15755|3:3|reload|esx.pm:load(210)|DATASTORE IP is
192.168.129.37 and DATASTORE_SHARE_PATH is /install/image/vmware_images
2010-03-22 16:51:17|15755|3:3|reload|esx.pm:load(211)|Entered ESX module,
loading esx3-basewinxp-v0 on resxi000 (on 128.82.128.252) for reservation 3
2010-03-22 16:51:17|15755|3:3|reload|esx.pm:load(212)|Datastore:
192.168.129.37:/install/image/vmware_images
2010-03-22 16:51:17|15755|3:3|reload|esx.pm:load(223)|VM info command:
/usr/lib/vmware-vcli/apps/vm/vminfo.pl --server '128' --vmname resxi000
--username 0 --password 'xxxxxxxxxxx'
Error connecting to server at 'https://128/sdk/webService': Perhaps host is not
a Virtual Center or ESX server
2010-03-22 16:51:17|15755|3:3|reload|esx.pm:load(226)|VM info output:
2010-03-22 16:51:17|15755|3:3|reload|utils.pm:run_ssh_command(6180)|executing
SSH command on 192.168.129.37:
|15755|3:3|reload| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
192.168.129.37 'rm -rf /install/image/vmware_images/inuse/resxi000' 2>&1
2010-03-22
16:51:18|15755|3:3|reload|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|15755|3:3|reload| none
2010-03-22 16:51:18|15755|3:3|reload|utils.pm:run_ssh_command(6276)|SSH command
executed on 192.168.129.37, returning (0, "none")
2010-03-22 16:51:18|15755|3:3|reload|esx.pm:load(262)|Removed old vm folder
2010-03-22 16:51:18|15755|3:3|reload|utils.pm:run_ssh_command(6180)|executing
SSH command on 192.168.129.37:
|15755|3:3|reload| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
192.168.129.37 'mkdir /install/image/vmware_images/inuse/resxi000' 2>&1
2010-03-22
16:51:18|15755|3:3|reload|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|15755|3:3|reload| none
2010-03-22 16:51:18|15755|3:3|reload|utils.pm:run_ssh_command(6276)|SSH command
executed on 192.168.129.37, returning (0, "none")
2010-03-22 16:51:18|15755|3:3|reload|utils.pm:run_ssh_command(6180)|executing
SSH command on 192.168.129.37:
|15755|3:3|reload| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
192.168.129.37 'cp
/install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0.vmdk
/install/image/vmware_images/inuse/resxi000/esx3-basewinxp-v0.vmdk' 2>&1
2010-03-22
16:51:18|15755|3:3|reload|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|15755|3:3|reload| cp: cannot stat
`/install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0.vmdk':
No such file or directory
2010-03-22 16:51:18|15755|3:3|reload|utils.pm:run_ssh_command(6272)|SSH command
executed on 192.168.129.37, command:
|15755|3:3|reload| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
192.168.129.37 'cp
/install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0.vmdk
/install/image/vmware_images/inuse/resxi000/esx3-basewinxp-v0.vmdk' 2>&1
|15755|3:3|reload| returning (1, "cp: cannot stat `/install/imag...")
2010-03-22 16:51:18|15755|3:3|reload|esx.pm:load(278)|COPIED VMDK SUCCESSFULLY
2010-03-22 16:51:18|15755|3:3|reload|utils.pm:run_ssh_command(6180)|executing
SSH command on 192.168.129.37:
|15755|3:3|reload| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
192.168.129.37 'cp
/install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0-flat.vmdk
/install/image/vmware_images/inuse/resxi000/esx3-basewinxp-v0-flat.vmdk' 2>&1
2010-03-22
16:51:18|15755|3:3|reload|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|15755|3:3|reload| cp: cannot stat
`/install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0-flat.vmdk':
No such file or directory
2010-03-22 16:51:18|15755|3:3|reload|utils.pm:run_ssh_command(6272)|SSH command
executed on 192.168.129.37, command:
|15755|3:3|reload| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
192.168.129.37 'cp
/install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0-flat.vmdk
/install/image/vmware_images/inuse/resxi000/esx3-basewinxp-v0-flat.vmdk' 2>&1
|15755|3:3|reload| returning (1, "cp: cannot stat `/install/imag...")
2010-03-22 16:51:18|15755|3:3|reload|utils.pm:run_ssh_command(6180)|executing
SSH command on 192.168.129.37:
|15755|3:3|reload| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
192.168.129.37 'grep adapterType
/install/image/vmware_images/inuse/resxi000/esx3-basewinxp-v0.vmdk 2>&1' 2>&1
2010-03-22
16:51:18|15755|3:3|reload|utils.pm:run_ssh_command(6262)|run_ssh_command output:
|15755|3:3|reload| grep:
/install/image/vmware_images/inuse/resxi000/esx3-basewinxp-v0.vmdk: No such
file or directory
2010-03-22 16:51:18|15755|3:3|reload|utils.pm:run_ssh_command(6272)|SSH command
executed on 192.168.129.37, command:
|15755|3:3|reload| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
192.168.129.37 'grep adapterType
/install/image/vmware_images/inuse/resxi000/esx3-basewinxp-v0.vmdk 2>&1' 2>&1
|15755|3:3|reload| returning (2, "grep: /install/image/vmware_im...")
2010-03-22 16:51:18|15755|3:3|reload|esx.pm:load(342)|eth0 MAC address set for
vcl assigned
Use of uninitialized value in concatenation (.) or string at
/usr/local/vcl/bin/../lib/VCL/Module/Provisioning/esx.pm line 343 (#1)
(W uninitialized) An undefined value was used as if it were already
defined. It was interpreted as a "" or a 0, but maybe it was a mistake.
To suppress this warning assign a defined value to your variables.
To help you figure out what was undefined, perl tells you what operation
you used the undefined value in. Note, however, that perl optimizes your
program and the operation displayed in the warning may not necessarily
appear literally in your program. For example, "that $foo" is
usually optimized into "that " . $foo, and the warning will refer to
the concatenation (.) operator, even though there is no . in your
program.
|15755|3:3|reload| ---- WARNING ----
|15755|3:3|reload| 2010-03-22
16:51:18|15755|3:3|reload|vcld:warning_handler(636)|Use of uninitialized value
in concatenation (.) or string at
/usr/local/vcl/bin/../lib/VCL/Module/Provisioning/esx.pm line 343.
|15755|3:3|reload| ( 0) utils.pm, notify (line: 737)
|15755|3:3|reload| (-1) vcld, warning_handler (line: 636)
|15755|3:3|reload| (-2) esx.pm, load (line: 343)
|15755|3:3|reload| (-3) new.pm, reload_image (line: 665)
|15755|3:3|reload| (-4) new.pm, process (line: 266)
|15755|3:3|reload| (-5) vcld, make_new_child (line: 594)
|15755|3:3|reload| (-6) vcld, main (line: 341)
|15755|3:3|reload| ---- WARNING ----
|15755|3:3|reload| 2010-03-22
16:51:18|15755|3:3|reload|vcld:warning_handler(636)|Use of uninitialized value
in concatenation (.) or string at
/usr/local/vcl/bin/../lib/VCL/Module/Provisioning/esx.pm line 353.
|15755|3:3|reload| ( 0) utils.pm, notify (line: 737)
|15755|3:3|reload| (-1) vcld, warning_handler (line: 636)
|15755|3:3|reload| (-2) esx.pm, load (line: 353)
|15755|3:3|reload| (-3) new.pm, reload_image (line: 665)
|15755|3:3|reload| (-4) new.pm, process (line: 266)
|15755|3:3|reload| (-5) vcld, make_new_child (line: 594)
|15755|3:3|reload| (-6) vcld, main (line: 341)
2010-03-22 16:51:18|15755|3:3|reload|esx.pm:load(353)|eth1 MAC address set for
vcl assigned
|15755|3:3|reload| ---- WARNING ----
|15755|3:3|reload| 2010-03-22
16:51:18|15755|3:3|reload|vcld:warning_handler(636)|Use of uninitialized value
in concatenation (.) or string at
/usr/local/vcl/bin/../lib/VCL/Module/Provisioning/esx.pm line 354.
|15755|3:3|reload| ( 0) utils.pm, notify (line: 737)
|15755|3:3|reload| (-1) vcld, warning_handler (line: 636)
|15755|3:3|reload| (-2) esx.pm, load (line: 354)
|15755|3:3|reload| (-3) new.pm, reload_image (line: 665)
|15755|3:3|reload| (-4) new.pm, process (line: 266)
|15755|3:3|reload| (-5) vcld, make_new_child (line: 594)
|15755|3:3|reload| (-6) vcld, main (line: 341)
2010-03-22 16:51:18|15755|3:3|reload|esx.pm:load(376)|wrote vmxarray to
/tmp/resxi000.vmx
2010-03-22 16:51:18|15755|3:3|reload|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/resxi000.vmx
192.168.129.37:/install/image/vmware_images/inuse/resxi000/esx3-basewinxp-v0.vmx
2>&1
2010-03-22 16:51:18|15755|3:3|reload|utils.pm:run_scp_command(6453)|scp
successful: attempt 1/3, exit status: 0, output: none
2010-03-22 16:51:18|15755|3:3|reload|esx.pm:load(401)|Register Command:
/usr/lib/vmware-vcli/apps/vm/vmregister.pl --server '128' --username 0
--password 'xxxxxxxxxxx' --vmxpath '[VCL]/inuse/resxi000/esx3-basewinxp-v0.vmx'
--operation register --vmname resxi000 --pool Resources --hostname
'128.82.128.252' --datacenter 'ha-datacenter'
Error connecting to server at 'https://128/sdk/webService': Perhaps host is not
a Virtual Center or ESX server
2010-03-22 16:51:18|15755|3:3|reload|esx.pm:load(404)|Registered:
2010-03-22 16:51:18|15755|3:3|reload|esx.pm:load(413)|Power on command:
/usr/lib/vmware-vcli/apps/vm/vmcontrol.pl --server '128' --vmname resxi000
--operation poweron --username 0 --password 'xxxxxxxxxxx'
Error connecting to server at 'https://128/sdk/webService': Perhaps host is not
a Virtual Center or ESX server
2010-03-22 16:51:18|15755|3:3|reload|esx.pm:load(416)|Powered on:
2010-03-22 16:51:18|15755|3:3|reload|esx.pm:load(505)|IP is known for resxi000
2010-03-22 16:51:18|15755|3:3|reload|esx.pm:load(511)|Waiting for ssh to come
up on resxi000
2010-03-22 16:51:19|15755|3:3|reload|esx.pm:load(528)|going to sleep 5 seconds,
waiting for computer to start SSH. Try 1
2010-03-22 16:51:21|15551|vcld:main(165)|lastcheckin time updated for
management node 1: 2010-03-22 16:51:21
2010-03-22 16:51:25|15755|3:3|reload|esx.pm:load(528)|going to sleep 5 seconds,
waiting for computer to start SSH. Try 2
2010-03-22 16:51:26|15551|vcld:main(165)|lastcheckin time updated for
management node 1: 2010-03-22 16:51:26
2010-03-22 16:51:31|15551|vcld:main(165)|lastcheckin time updated for
management node 1: 2010-03-22 16:51:31
2010-03-22 16:51:31|15755|3:3|reload|esx.pm:load(528)|going to sleep 5 seconds,
waiting for computer to start SSH. Try 3
2010-03-22 16:51:36|15551|vcld:main(165)|lastcheckin time updated for
management node 1: 2010-03-22 16:51:36
2010-03-22 16:51:37|15755|3:3|reload|esx.pm:load(528)|going to sleep 5 seconds,
waiting for computer to start SSH. Try 4
2010-03-22 16:51:41|15551|vcld:main(165)|lastcheckin time updated for
management node 1: 2010-03-22 16:51:41
2010-03-22 16:51:44|15755|3:3|reload|esx.pm:load(528)|going to sleep 5 seconds,
waiting for computer to start SSH. Try 5
2010-03-22 16:51:46|15551|vcld:main(165)|lastcheckin time updated for
management node 1: 2010-03-22 16:51:46
2010-03-22 16:51:50|15755|3:3|reload|esx.pm:load(528)|going to sleep 5 seconds,
waiting for computer to start SSH. Try 6
2010-03-22 16:51:51|15551|vcld:main(165)|lastcheckin time updated for
management node 1: 2010-03-22 16:51:51
2010-03-22 16:51:56|15755|3:3|reload|esx.pm:load(528)|going to sleep 5 seconds,
waiting for computer to start SSH. Try 7
2010-03-22 16:51:56|15551|vcld:main(165)|lastcheckin time updated for
management node 1: 2010-03-22 16:51:56
2010-03-22 16:52:01|15551|vcld:main(165)|lastcheckin time updated for
management node 1: 2010-03-22 16:52:01
2010-03-22 16:52:02|15755|3:3|reload|esx.pm:load(528)|going to sleep 5 seconds,
waiting for computer to start SSH. Try 8
Thank you,
Amit
> -----Original Message-----
> From: Ryan Johnson [mailto:rjoh...@gwmail.gwu.edu]
> Sent: Monday, March 22, 2010 4:08 PM
> To: vcl-dev@incubator.apache.org
> Subject: Re: Reservation Error:
>
> No what I did was avoid running ssh commands on the Esxi entirely by
> specifying the IP of a remote server which is hosting a network file system
> as the datastorepath column in the vmprofile table.
>
> On Mon, Mar 22, 2010 at 3:59 PM, Kumar, Amit H. <ahku...@odu.edu> wrote:
>
> > Hi Ryan,
