You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@vcl.apache.org by Jeffrey Wisman <je...@csueastbay.edu> on 2010/04/06 04:32:45 UTC
Re: Reloading VM After Image Capture and VM Registration: FAILS
Were you ever able to resolve this issue? It sounds an awful lot like our
problem. We were advised to purchase the VMWare license, but outside of
doing that, I'm at a loss as to what to do.
Thanks,
Jeff
On Wed, Mar 24, 2010 at 3:02 PM, Kumar, Amit H. <AH...@odu.edu> wrote:
> HI All ....
>
> I am close to getting this first step done. After the Image capture and VM
> registration with the VMhost it fails to power on the VMmachine. Also I
> notice that the VM registered on ESXi VMhost shows up as "Unknown (invalid)"
>
> Not sure what went wrong:
>
> Please advise:
>
> 2010-03-24 17:35:11|5443|2:2|image|vcld:main(276)|reservation 2 is NOT
> already being processed
>
> |5443|2:2|image| ---- WARNING ----
> |5443|2:2|image| 2010-03-24 17:35:12|5443|2:2|image|utils.pm:get_request_info(5218)|preferredimageid
> is not set for computer id=3
> |5443|2:2|image| ( 0) utils.pm, notify (line: 737)
> |5443|2:2|image| (-1) utils.pm, get_request_info (line: 5218)
> |5443|2:2|image| (-2) vcld, main (line: 280)
>
> 2010-03-24 17:35:12|5443|2:2|image|utils.pm:get_request_info(5354)|standalone
> affiliation found: Local
> 2010-03-24 17:35:12|5443|2:2|image|utils.pm:get_management_node_info(6815)|management
> node info retrieved from database for colbert
> 2010-03-24 17:35:12|5443|2:2|image|vcld:main(281)|retrieved request
> information from database
> 2010-03-24 17:35:12|5443|2:2|image|utils.pm:get_management_node_info(6815)|management
> node info retrieved from database for colbert
> 2010-03-24
> 17:35:12|5443|2:2|image|DataStructure.pm:is_parent_reservation(854)|returning
> true: parent reservation ID for this request: 2
> 2010-03-24 17:35:12|5443|2:2|image|utils.pm:update_request_state(2186)|request
> 2 state updated to: pending, laststate to: image
> 2010-03-24 17:35:12|5443|2:2|image|utils.pm:insertloadlog(4710)|inserted
> computer=3, begin, beginning to process, state is image
> 2010-03-24 17:35:12|5443|2:2|image|vcld:make_new_child(509)|loaded
> VCL::image module
> 2010-03-24 17:35:12|5445|2:2|image|vcld:make_new_child(582)|vcld
> environment variable set to 0 for this process
> 2010-03-24 17:35:12|5445|2:2|image|Module.pm:new(132)|constructor called,
> class=VCL::image
> 2010-03-24 17:35:12|5445|2:2|image|Module.pm:new(154)|VCL::image object
> created
> 2010-03-24 17:35:12|5443|2:2|image|vcld:make_new_child(566)|current number
> of forked kids: 1
> 2010-03-24 17:35:12|5445|2:2|image|State.pm:initialize(85)|obtained a
> database handle for this state process, stored as $ENV{dbh}
> 2010-03-24 17:35:12|5445|2:2|image|State.pm:check_image_os(839)|no
> corrections need to be made to image OS: esx35
> 2010-03-24
> 17:35:12|5445|2:2|image|DataStructure.pm:is_parent_reservation(854)|returning
> true: parent reservation ID for this request: 2
> 2010-03-24 17:35:12|5445|2:2|image|utils.pm:rename_vcld_process(7863)|reservation
> count: 1
> 2010-03-24 17:35:12|5445|2:2|image|utils.pm:rename_vcld_process(7882)|PARENTIMAGE:
> 1
> 2010-03-24 17:35:12|5445|2:2|image|utils.pm:rename_vcld_process(7883)|SUBIMAGE:
> 0
> 2010-03-24 17:35:12|5445|2:2|image|utils.pm:rename_vcld_process(7901)|renamed
> process to 'vcld VCL::image 2:2 image imaging'
> 2010-03-24
> 17:35:12|5445|2:2|image|DataStructure.pm:is_parent_reservation(854)|returning
> true: parent reservation ID for this request: 2
> 2010-03-24
> 17:35:12|5445|2:2|image|DataStructure.pm:is_parent_reservation(854)|returning
> true: parent reservation ID for this request: 2
> 2010-03-24 17:35:12|5445|2:2|image|State.pm:initialize(121)|attempting to
> load provisioning module: VCL::Module::Provisioning::esx
> 2010-03-24 17:35:12|5445|2:2|image|esx.pm:initialize(138)|esx vmware
> toolkit root path found: /usr/lib/vmware-vcli/apps
> 2010-03-24 17:35:12|5445|2:2|image|esx.pm:initialize(140)|vmware ESX
> module initialized
> 2010-03-24
> 17:35:12|5445|2:2|image|State.pm:initialize(127)|VCL::Module::Provisioning::esx
> module loaded
> 2010-03-24 17:35:12|5445|2:2|image|Module.pm:new(132)|constructor called,
> class=VCL::Module::Provisioning::esx
> 2010-03-24
> 17:35:12|5445|2:2|image|Module.pm:new(154)|VCL::Module::Provisioning::esx
> object created
> 2010-03-24 17:35:12|5445|2:2|image|esx.pm:initialize(138)|esx vmware
> toolkit root path found: /usr/lib/vmware-vcli/apps
> 2010-03-24 17:35:12|5445|2:2|image|esx.pm:initialize(140)|vmware ESX
> module initialized
> 2010-03-24
> 17:35:12|5445|2:2|image|State.pm:initialize(131)|VCL::Module::Provisioning::esx
> provisioner object created
> 2010-03-24 17:35:12|5445|2:2|image|State.pm:initialize(145)|attempting to
> load OS module: VCL::Module::OS::Linux
> 2010-03-24
> 17:35:12|5445|2:2|image|State.pm:initialize(151)|VCL::Module::OS::Linux
> module loaded
> 2010-03-24 17:35:12|5445|2:2|image|Module.pm:new(132)|constructor called,
> class=VCL::Module::OS::Linux
> 2010-03-24
> 17:35:12|5445|2:2|image|Module.pm:new(154)|VCL::Module::OS::Linux object
> created
> 2010-03-24
> 17:35:12|5445|2:2|image|State.pm:initialize(154)|VCL::Module::OS::Linux OS
> object created
> 2010-03-24 17:35:12|5445|2:2|image|State.pm:initialize(169)|returning 1
> 2010-03-24 17:35:12|5445|2:2|image|vcld:make_new_child(591)|VCL::image
> object created and initialized
> No recipient addresses found in header
> 2010-03-24 17:35:12|5445|2:2|image|utils.pm:mail(1348)|SUCCESS -- Sending
> mail To: , VCL IMAGE Creation Started: esx3-basewinxp-v0
> 2010-03-24 17:35:12|5445|2:2|image|utils.pm:run_ssh_command(6180)|executing
> SSH command on 192.168.129.37:
> |5445|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-24 17:35:12|5445|2:2|image|utils.pm:run_ssh_command(6262)|run_ssh_command
> output:
> |5445|2:2|image| none
> 2010-03-24 17:35:12|5445|2:2|image|utils.pm:run_ssh_command(6276)|SSH
> command executed on 192.168.129.37, returning (0, "none")
>
> |5445|2:2|image| ---- WARNING ----
> |5445|2:2|image| 2010-03-24 17:35:12|5445|2:2|image|esx.pm:does_image_exist(930)|image
> /install/image/vmware_images/golden/esx3-basewinxp-v0 does NOT exists
> |5445|2:2|image| ( 0) utils.pm, notify (line: 737)
> |5445|2:2|image| (-1) esx.pm, does_image_exist (line: 930)
> |5445|2:2|image| (-2) image.pm, process (line: 135)
> |5445|2:2|image| (-3) vcld, make_new_child (line: 594)
> |5445|2:2|image| (-4) vcld, main (line: 341)
>
> 2010-03-24 17:35:12|5445|2:2|image|image.pm:process(145)|image
> esx3-basewinxp-v0 does not exist in the repository
> 2010-03-24 17:35:12|5445|2:2|image|DataStructure.pm:_automethod(697)|data
> structure updated: $self->request_data->{reservation}{2}{image}{lastupdate}
> |5445|2:2|image| image_lastupdate = 2010-03-24 17:35:12
> 2010-03-24 17:35:12|5445|2:2|image|DataStructure.pm:_automethod(697)|data
> structure updated:
> $self->request_data->{reservation}{2}{imagerevision}{datecreated}
> |5445|2:2|image| imagerevision_date_created = 2010-03-24 17:35:12
> 2010-03-24 17:35:12|5445|2:2|image|image.pm:process(161)|calling
> provisioning module's capture() subroutine
> 2010-03-24 17:35:12|5445|2:2|image|esx.pm:
> capture(593)|**********************************************************
> 2010-03-24 17:35:12|5445|2:2|image|esx.pm:capture(594)|Entering ESX
> Capture routine
> 2010-03-24 17:35:12|5445|2:2|image|utils.pm:run_ssh_command(6180)|executing
> SSH command on 192.168.129.37:
> |5445|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/esx3-basewinxp-v0
> 2>&1' 2>&1
> 2010-03-24 17:35:12|5445|2:2|image|utils.pm:run_ssh_command(6262)|run_ssh_command
> output:
> |5445|2:2|image| esx3-basewinxp-v0-flat.vmdk
> |5445|2:2|image| esx3-basewinxp-v0.nvram
> |5445|2:2|image| esx3-basewinxp-v0.vmdk
> |5445|2:2|image| esx3-basewinxp-v0.vmsd
> |5445|2:2|image| esx3-basewinxp-v0.vmx
> |5445|2:2|image| esx3-basewinxp-v0.vmxf
> |5445|2:2|image| vmware-0.log
> |5445|2:2|image| vmware-1.log
> |5445|2:2|image| vmware-2.log
> |5445|2:2|image| vmware-3.log
> |5445|2:2|image| vmware-4.log
> |5445|2:2|image| vmware-5.log
> |5445|2:2|image| vmware.log
> 2010-03-24 17:35:12|5445|2:2|image|utils.pm:run_ssh_command(6276)|SSH
> command executed on 192.168.129.37, returning (0,
> "esx3-basewinxp-v0-flat.vmdk es...")
> 2010-03-24 17:35:12|5445|2:2|image|esx.pm:capture(646)|found previous
> name= esx3-basewinxp-v0
> 2010-03-24 17:35:12|5445|2:2|image|esx.pm:capture(648)|SSHing to node to
> configure currentimage.txt
> 2010-03-24 17:35:12|5445|2:2|image|utils.pm:run_ssh_command(6180)|executing
> SSH command on esx3-basewinxp-v0:
> |5445|2:2|image| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
> esx3-basewinxp-v0 'echo esx3-basewinxp-v0 > /root/currentimage.txt' 2>&1
> 2010-03-24 17:35:17|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:35:17
> 2010-03-24 17:35:22|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:35:22
> 2010-03-24 17:35:22|5445|2:2|image|utils.pm:run_ssh_command(6262)|run_ssh_command
> output:
> |5445|2:2|image| bash: /root/currentimage.txt: No such file or directory
> 2010-03-24 17:35:22|5445|2:2|image|utils.pm:run_ssh_command(6272)|SSH
> command executed on esx3-basewinxp-v0, command:
> |5445|2:2|image| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
> esx3-basewinxp-v0 'echo esx3-basewinxp-v0 > /root/currentimage.txt' 2>&1
> |5445|2:2|image| returning (1, "bash: /root/currentimage.txt: ...")
> 2010-03-24 17:35:22|5445|2:2|image|esx.pm:capture(658)|Power off command:
> /usr/lib/vmware-vcli/apps/vm/vmcontrol.pl --server 'esx35-hypervisor-1'
> --vmname esx3-basewinxp-v0 --operation poweroff --username root --password
> 'xxxxxxxxxxx'
> 2010-03-24 17:35:26|5445|2:2|image|esx.pm:capture(661)|Powered off:
> |5445|2:2|image| virtual machine 'esx3-basewinxp-v0' under host
> esx35-hypervisor-1.odu.edu powered off
> 2010-03-24 17:35:26|5445|2:2|image|esx.pm:capture(663)|Waiting 5 seconds
> for power off
> 2010-03-24 17:35:27|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:35:27
> 2010-03-24 17:35:31|5445|2:2|image|utils.pm:run_ssh_command(6180)|executing
> SSH command on 192.168.129.37:
> |5445|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-24 17:35:31|5445|2:2|image|utils.pm:run_ssh_command(6262)|run_ssh_command
> output:
> |5445|2:2|image| none
> 2010-03-24 17:35:31|5445|2:2|image|utils.pm:run_ssh_command(6276)|SSH
> command executed on 192.168.129.37, returning (0, "none")
> 2010-03-24 17:35:31|5445|2:2|image|utils.pm:run_ssh_command(6180)|executing
> SSH command on 192.168.129.37:
> |5445|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/esx3-basewinxp-v0/esx3-basewinxp-v0.vmdk
> /install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0.vmdk'
> 2>&1
> 2010-03-24 17:35:31|5445|2:2|image|utils.pm:run_ssh_command(6262)|run_ssh_command
> output:
> |5445|2:2|image| none
> 2010-03-24 17:35:31|5445|2:2|image|utils.pm:run_ssh_command(6276)|SSH
> command executed on 192.168.129.37, returning (0, "none")
> 2010-03-24 17:35:31|5445|2:2|image|esx.pm:capture(679)|COPIED VMDK
> SUCCESSFULLY
> 2010-03-24 17:35:31|5445|2:2|image|utils.pm:run_ssh_command(6180)|executing
> SSH command on 192.168.129.37:
> |5445|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/esx3-basewinxp-v0/esx3-basewinxp-v0.vmx
> /install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0.vmx'
> 2>&1
> 2010-03-24 17:35:32|5445|2:2|image|utils.pm:run_ssh_command(6262)|run_ssh_command
> output:
> |5445|2:2|image| none
> 2010-03-24 17:35:32|5445|2:2|image|utils.pm:run_ssh_command(6276)|SSH
> command executed on 192.168.129.37, returning (0, "none")
> 2010-03-24 17:35:32|5445|2:2|image|esx.pm:capture(688)|COPIED VMX
> SUCCESSFULLY
> 2010-03-24 17:35:32|5445|2:2|image|esx.pm:capture(691)|Rewriting VMDK and
> VMX files with new image name
> 2010-03-24 17:35:32|5445|2:2|image|utils.pm:run_ssh_command(6180)|executing
> SSH command on 192.168.129.37:
> |5445|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/esx3-basewinxp-v0/"
> /install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0.vmx'
> 2>&1
> 2010-03-24 17:35:32|5445|2:2|image|utils.pm:run_ssh_command(6262)|run_ssh_command
> output:
> |5445|2:2|image| none
> 2010-03-24 17:35:32|5445|2:2|image|utils.pm:run_ssh_command(6276)|SSH
> command executed on 192.168.129.37, returning (0, "none")
> 2010-03-24 17:35:32|5445|2:2|image|utils.pm:run_ssh_command(6180)|executing
> SSH command on 192.168.129.37:
> |5445|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/esx3-basewinxp-v0/"
> /install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0.vmdk'
> 2>&1
> 2010-03-24 17:35:32|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:35:32
> 2010-03-24 17:35:32|5445|2:2|image|utils.pm:run_ssh_command(6262)|run_ssh_command
> output:
> |5445|2:2|image| none
> 2010-03-24 17:35:32|5445|2:2|image|utils.pm:run_ssh_command(6276)|SSH
> command executed on 192.168.129.37, returning (0, "none")
> 2010-03-24 17:35:32|5445|2:2|image|esx.pm:capture(705)|Preparing to ssh to
> 192.168.129.37 copy vmdk-flat from
> /install/image/vmware_images/inuse/esx3-basewinxp-v0/esx3-basewinxp-v0-flat.vmdk
> to
> /install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0-flat.vmdk
> 2010-03-24 17:35:32|5445|2:2|image|esx.pm:capture(706)|SSHing to copy
> vmdk-flat file
> 2010-03-24 17:35:32|5445|2:2|image|utils.pm:run_ssh_command(6180)|executing
> SSH command on 192.168.129.37:
> |5445|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/esx3-basewinxp-v0/esx3-basewinxp-v0-flat.vmdk
> /install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0-flat.vmdk'
> 2>&1
> 2010-03-24 17:35:37|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:35:37
> 2010-03-24 17:35:42|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:35:42
> 2010-03-24 17:35:47|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:35:47
> 2010-03-24 17:35:52|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:35:52
> 2010-03-24 17:35:57|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:35:57
> 2010-03-24 17:36:02|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:36:02
> 2010-03-24 17:36:07|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:36:07
> 2010-03-24 17:36:12|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:36:12
> 2010-03-24 17:36:17|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:36:17
> 2010-03-24 17:36:22|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:36:22
> 2010-03-24 17:36:27|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:36:27
> 2010-03-24 17:36:32|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:36:32
> 2010-03-24 17:36:37|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:36:37
> 2010-03-24 17:36:42|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:36:42
> 2010-03-24 17:36:47|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:36:47
> 2010-03-24 17:36:52|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:36:52
> 2010-03-24 17:36:57|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:36:57
> 2010-03-24 17:37:02|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:37:02
> 2010-03-24 17:37:07|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:37:07
> 2010-03-24 17:37:12|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:37:12
> 2010-03-24 17:37:17|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:37:17
> 2010-03-24 17:37:22|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:37:22
> 2010-03-24 17:37:27|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:37:27
> 2010-03-24 17:37:32|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:37:32
> 2010-03-24 17:37:37|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:37:37
> 2010-03-24 17:37:42|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:37:42
> 2010-03-24 17:37:47|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:37:47
> 2010-03-24 17:37:53|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:37:53
> 2010-03-24 17:37:58|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:37:58
> 2010-03-24 17:38:03|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:38:03
> 2010-03-24 17:38:08|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:38:08
> 2010-03-24 17:38:13|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:38:13
> 2010-03-24 17:38:18|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:38:18
> 2010-03-24 17:38:20|5445|2:2|image|utils.pm:run_ssh_command(6262)|run_ssh_command
> output:
> |5445|2:2|image| none
> 2010-03-24 17:38:20|5445|2:2|image|utils.pm:run_ssh_command(6276)|SSH
> command executed on 192.168.129.37, returning (0, "none")
> 2010-03-24 17:38:20|5445|2:2|image|image.pm:process(162)|esx3-basewinxp-v0
> image was successfully captured by the provisioning module
> 2010-03-24 17:38:20|5445|2:2|image|image.pm:process(219)|esx3-basewinxp-v0
> image files successfully saved
> 2010-03-24 17:38:20|5445|2:2|image|utils.pm:update_request_state(2186)|request
> 2 state updated to: completed, laststate to: image
> 2010-03-24 17:38:20|5445|2:2|image|image.pm:process(222)|request state
> updated to completed, laststate to image
> 2010-03-24 17:38:20|5445|2:2|image|esx.pm:get_image_size(960)|getting size
> of image: esx3-basewinxp-v0
> 2010-03-24 17:38:20|5445|2:2|image|utils.pm:run_ssh_command(6180)|executing
> SSH command on 192.168.129.37:
> |5445|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-24 17:38:21|5445|2:2|image|utils.pm:run_ssh_command(6262)|run_ssh_command
> output:
> |5445|2:2|image| total 4198412
> |5445|2:2|image| 4198404 esx3-basewinxp-v0-flat.vmdk
> |5445|2:2|image| 4 esx3-basewinxp-v0.vmdk
> |5445|2:2|image| 4 esx3-basewinxp-v0.vmx
> 2010-03-24 17:38:21|5445|2:2|image|utils.pm:run_ssh_command(6276)|SSH
> command executed on 192.168.129.37, returning (0, "total 4198412 4198404
> esx3-bas...")
> 2010-03-24 17:38:21|5445|2:2|image|image.pm:process(231)|size of
> esx3-basewinxp-v0: 4100
> 2010-03-24 17:38:21|5445|2:2|image|DataStructure.pm:_automethod(697)|data
> structure updated: $self->request_data->{reservation}{2}{image}{size}
> |5445|2:2|image| image_size = 4100
> 2010-03-24 17:38:21|5445|2:2|image|image.pm:process(260)|image and
> imagerevision tables updated for image=10, imagerevision=11,
> name=esx3-basewinxp-v0, lastupdate=2010-03-24 17:35:12, deleted=0, size=4100
> 2010-03-24 17:38:22|5445|2:2|image|utils.pm:mail(1348)|SUCCESS -- Sending
> mail To: root@localhost, VCL -- No Apps (ESXi WinXP) Image Creation
> Succeeded
> No recipient addresses found in header
> 2010-03-24 17:38:22|5445|2:2|image|utils.pm:mail(1348)|SUCCESS -- Sending
> mail To: , VCL IMAGE Creation Completed: esx3-basewinxp-v0
> 2010-03-24 17:38:22|5445|2:2|image|utils.pm:insertloadlog(4710)|inserted
> computer=3, loadimagevmware, VCL::utils::insert_reload_request: switching
> request state to reload
> 2010-03-24 17:38:22|5445|2:2|image|utils.pm:update_computer_state(2228)|computer
> 3 state updated to: reload
> 2010-03-24 17:38:22|5445|2:2|image|utils.pm:insert_reload_request(9117)|req=2:
> setting computerid 3 into reload state
> 2010-03-24 17:38:22|5445|2:2|image|utils.pm:insert_request(9020)|inserted
> new reload request into request table, request id=3
> 2010-03-24 17:38:22|5445|2:2|image|utils.pm:insert_request(9051)|inserted
> new reload request into reservation table, reservation id=3
> 2010-03-24 17:38:22|5445|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-24 17:38:22|5445|2:2|image|utils.pm:insertloadlog(4710)|inserted
> computer=3, info, VCL::utils::insert_reload_request: created new reload
> request
> 2010-03-24 17:38:22|5445|2:2|image|image.pm:reservation_successful(348)|inserted
> reload request into database for computer id=3
> 2010-03-24 17:38:22|5445|2:2|image|utils.pm:switch_state(8018)|called from
> VCL::image::reservation_successful(351)
> 2010-03-24 17:38:22|5445|2:2|image|utils.pm:switch_state(8054)|parent:
> parent reservation ID for this request: 2
> 2010-03-24 17:38:22|5445|2:2|image|utils.pm:insertloadlog(4710)|inserted
> computer=3, info, VCL::image: switching request state to complete
> 2010-03-24 17:38:22|5445|2:2|image|utils.pm:update_request_state(2186)|request
> 2 state updated to: complete, laststate to: image
> 2010-03-24 17:38:22|5445|2:2|image|utils.pm:switch_state(8078)|req=2:
> request state changed: image->complete, laststate: image->image
> 2010-03-24 17:38:22|5445|2:2|image|utils.pm:insertloadlog(4710)|inserted
> computer=3, info, VCL::image: request state changed to complete, laststate
> to image
> 2010-03-24 17:38:22|5445|2:2|image|utils.pm:switch_state(8088)|req=2:
> computer state not specified, esx3-basewinxp-v0 state not changed
> 2010-03-24 17:38:22|5445|2:2|image|utils.pm:switch_state(8106)|req=2: log
> table id=0, ending set to EOR
> 2010-03-24 17:38:22|5445|2:2|image|utils.pm:insertloadlog(4710)|inserted
> computer=3, info, VCL::image: process exiting
> 2010-03-24 17:38:22|5445|2:2|image|utils.pm:switch_state(8122)|req=2:
> process exiting
> 2010-03-24 17:38:22|5445|2:2|image|State.pm:DESTROY(905)|destructor called,
> ref($self)=VCL::image
> 2010-03-24 17:38:22|5445|2:2|image|utils.pm:delete_computerloadlog_reservation(7551)|removing
> computerloadlog entries matching loadstate = begin
> 2010-03-24 17:38:22|5445|2:2|image|utils.pm:delete_computerloadlog_reservation(7598)|deleted
> rows from computerloadlog for reservation id=2
> 2010-03-24 17:38:22|5445|2:2|image|State.pm:DESTROY(912)|removed
> computerloadlog rows with loadstate=begin for reservation
> 2010-03-24 17:38:22|5445|2:2|image|State.pm:DESTROY(924)|number of database
> handles state process created: 1
> 2010-03-24 17:38:22|5445|2:2|image|State.pm:DESTROY(933)|process has a
> database handle stored in $ENV{dbh}, attempting disconnect
> 2010-03-24 17:38:22|5445|2:2|image|State.pm:DESTROY(935)|$ENV{dbh}:
> database disconnect successful
> 2010-03-24 17:38:22|5445|2:2|image|State.pm:DESTROY(949)|VCL::image process
> 5445 exiting
> 2010-03-24 17:38:22|5443|vcld:REAPER(744)|VCL process exited for
> reservation 2
> 2010-03-24 17:38:22|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:38:22
> 2010-03-24 17:38:22|5443|3:3|reload|utils.pm:reservation_being_processed(9634)|computerloadlog
> 'begin' entry does NOT exist for reservation 3
> 2010-03-24 17:38:22|5443|3:3|reload|utils.pm:reservation_being_processed(9686)|reservation
> is NOT currently being processed
> 2010-03-24 17:38:22|5443|3:3|reload|vcld:main(276)|reservation 3 is NOT
> already being processed
>
> |5443|3:3|reload| ---- WARNING ----
> |5443|3:3|reload| 2010-03-24 17:38:22|5443|3:3|reload|utils.pm:get_request_info(5218)|preferredimageid
> is not set for computer id=3
> |5443|3:3|reload| ( 0) utils.pm, notify (line: 737)
> |5443|3:3|reload| (-1) utils.pm, get_request_info (line: 5218)
> |5443|3:3|reload| (-2) vcld, main (line: 280)
>
> 2010-03-24 17:38:22|5443|3:3|reload|utils.pm:get_request_info(5354)|standalone
> affiliation found: Local
> 2010-03-24 17:38:22|5443|3:3|reload|utils.pm:get_management_node_info(6815)|management
> node info retrieved from database for colbert
> 2010-03-24 17:38:22|5443|3:3|reload|vcld:main(281)|retrieved request
> information from database
> 2010-03-24
> 17:38:22|5443|3:3|reload|DataStructure.pm:is_parent_reservation(854)|returning
> true: parent reservation ID for this request: 3
> 2010-03-24 17:38:22|5443|3:3|reload|utils.pm:update_request_state(2186)|request
> 3 state updated to: pending, laststate to: reload
> 2010-03-24 17:38:22|5443|3:3|reload|utils.pm:insertloadlog(4710)|inserted
> computer=3, begin, beginning to process, state is reload
> 2010-03-24 17:38:22|5443|3:3|reload|vcld:make_new_child(501)|request will
> be processed by new.pm
> 2010-03-24 17:38:22|5443|3:3|reload|vcld:make_new_child(509)|loaded
> VCL::new module
> 2010-03-24 17:38:22|5665|3:3|reload|vcld:make_new_child(582)|vcld
> environment variable set to 0 for this process
> 2010-03-24 17:38:22|5665|3:3|reload|Module.pm:new(132)|constructor called,
> class=VCL::new
> 2010-03-24 17:38:22|5665|3:3|reload|Module.pm:new(154)|VCL::new object
> created
> 2010-03-24 17:38:22|5443|3:3|reload|vcld:make_new_child(566)|current number
> of forked kids: 1
> 2010-03-24 17:38:22|5665|3:3|reload|State.pm:initialize(85)|obtained a
> database handle for this state process, stored as $ENV{dbh}
> 2010-03-24 17:38:22|5665|3:3|reload|State.pm:check_image_os(820)|no
> corrections need to be made, not an imaging request, returning 1
> 2010-03-24
> 17:38:22|5665|3:3|reload|DataStructure.pm:is_parent_reservation(854)|returning
> true: parent reservation ID for this request: 3
> 2010-03-24 17:38:22|5665|3:3|reload|utils.pm:rename_vcld_process(7863)|reservation
> count: 1
> 2010-03-24 17:38:22|5665|3:3|reload|utils.pm:rename_vcld_process(7882)|PARENTIMAGE:
> 1
> 2010-03-24 17:38:22|5665|3:3|reload|utils.pm:rename_vcld_process(7883)|SUBIMAGE:
> 0
> 2010-03-24 17:38:22|5665|3:3|reload|utils.pm:rename_vcld_process(7901)|renamed
> process to 'vcld VCL::new 3:3 reload'
> 2010-03-24
> 17:38:22|5665|3:3|reload|DataStructure.pm:is_parent_reservation(854)|returning
> true: parent reservation ID for this request: 3
> 2010-03-24
> 17:38:22|5665|3:3|reload|DataStructure.pm:is_parent_reservation(854)|returning
> true: parent reservation ID for this request: 3
> 2010-03-24 17:38:22|5665|3:3|reload|State.pm:initialize(121)|attempting to
> load provisioning module: VCL::Module::Provisioning::esx
> 2010-03-24 17:38:22|5443|2:2|complete|vcld:main(250)|request deleted
> 2010-03-24 17:38:22|5665|3:3|reload|esx.pm:initialize(138)|esx vmware
> toolkit root path found: /usr/lib/vmware-vcli/apps
> 2010-03-24 17:38:22|5665|3:3|reload|esx.pm:initialize(140)|vmware ESX
> module initialized
> 2010-03-24
> 17:38:22|5665|3:3|reload|State.pm:initialize(127)|VCL::Module::Provisioning::esx
> module loaded
> 2010-03-24 17:38:22|5665|3:3|reload|Module.pm:new(132)|constructor called,
> class=VCL::Module::Provisioning::esx
> 2010-03-24
> 17:38:22|5665|3:3|reload|Module.pm:new(154)|VCL::Module::Provisioning::esx
> object created
> 2010-03-24 17:38:22|5665|3:3|reload|esx.pm:initialize(138)|esx vmware
> toolkit root path found: /usr/lib/vmware-vcli/apps
> 2010-03-24 17:38:22|5665|3:3|reload|esx.pm:initialize(140)|vmware ESX
> module initialized
> 2010-03-24
> 17:38:22|5665|3:3|reload|State.pm:initialize(131)|VCL::Module::Provisioning::esx
> provisioner object created
> 2010-03-24 17:38:22|5665|3:3|reload|State.pm:initialize(145)|attempting to
> load OS module: VCL::Module::OS::Linux
> 2010-03-24
> 17:38:22|5665|3:3|reload|State.pm:initialize(151)|VCL::Module::OS::Linux
> module loaded
> 2010-03-24 17:38:22|5665|3:3|reload|Module.pm:new(132)|constructor called,
> class=VCL::Module::OS::Linux
> 2010-03-24
> 17:38:22|5665|3:3|reload|Module.pm:new(154)|VCL::Module::OS::Linux object
> created
> 2010-03-24
> 17:38:22|5665|3:3|reload|State.pm:initialize(154)|VCL::Module::OS::Linux OS
> object created
> 2010-03-24 17:38:22|5665|3:3|reload|State.pm:initialize(169)|returning 1
> 2010-03-24 17:38:22|5665|3:3|reload|vcld:make_new_child(591)|VCL::new
> object created and initialized
> 2010-03-24
> 17:38:22|5665|3:3|reload|DataStructure.pm:is_parent_reservation(854)|returning
> true: parent reservation ID for this request: 3
> 2010-03-24
> 17:38:22|5665|3:3|reload|DataStructure.pm:get_computer_state_name(1946)|attempting
> to retrieve current state of computer esx3-basewinxp-v0 from the database
> 2010-03-24
> 17:38:22|5665|3:3|reload|DataStructure.pm:get_computer_state_name(1977)|retrieved
> current state of computer esx3-basewinxp-v0 from the database: reload
> 2010-03-24 17:38:22|5665|3:3|reload|DataStructure.pm:_automethod(697)|data
> structure updated:
> $self->request_data->{reservation}{3}{computer}{state}{name}
> |5665|3:3|reload| computer_state_name = reload
>
> |5665|3:3|reload| ---- WARNING ----
> |5665|3:3|reload| 2010-03-24
> 17:38:22|5665|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}
> |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> |5665|3:3|reload| (-1) DataStructure.pm, _automethod (line: 675)
> |5665|3:3|reload| (-2) Autoload.pm, __ANON__ (line: 80)
> |5665|3:3|reload| (-3) new.pm, process (line: 106)
> |5665|3:3|reload| (-4) vcld, make_new_child (line: 594)
> |5665|3:3|reload| (-5) vcld, main (line: 341)
>
>
> |5665|3:3|reload| ---- WARNING ----
> |5665|3:3|reload| 2010-03-24
> 17:38:22|5665|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}
> |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> |5665|3:3|reload| (-1) DataStructure.pm, _automethod (line: 675)
> |5665|3:3|reload| (-2) Autoload.pm, __ANON__ (line: 80)
> |5665|3:3|reload| (-3) new.pm, process (line: 107)
> |5665|3:3|reload| (-4) vcld, make_new_child (line: 594)
> |5665|3:3|reload| (-5) vcld, main (line: 341)
>
> 2010-03-24 17:38:22|5665|3:3|reload|utils.pm:get_management_node_id(9364)|environment
> variable: 1
> 2010-03-24 17:38:22|5665|3:3|reload|new.pm:process(134)|reservation is
> parent = 1
> 2010-03-24 17:38:22|5665|3:3|reload|new.pm:process(135)|preload only = 0
> 2010-03-24 17:38:22|5665|3:3|reload|new.pm:process(136)|originating
> request state = reload
> 2010-03-24 17:38:22|5665|3:3|reload|new.pm:process(137)|originating
> request laststate = image
> 2010-03-24 17:38:22|5665|3:3|reload|new.pm:process(138)|originating
> computer state = reload
> 2010-03-24 17:38:22|5665|3:3|reload|new.pm:process(139)|originating
> computer type = virtualmachine
> 2010-03-24
> 17:38:22|5665|3:3|reload|DataStructure.pm:is_parent_reservation(854)|returning
> true: parent reservation ID for this request: 3
> 2010-03-24
> 17:38:22|5665|3:3|reload|DataStructure.pm:get_computer_state_name(1946)|attempting
> to retrieve current state of computer esx3-basewinxp-v0 from the database
> 2010-03-24
> 17:38:22|5665|3:3|reload|DataStructure.pm:get_computer_state_name(1977)|retrieved
> current state of computer esx3-basewinxp-v0 from the database: reload
> 2010-03-24 17:38:22|5665|3:3|reload|DataStructure.pm:_automethod(697)|data
> structure updated:
> $self->request_data->{reservation}{3}{computer}{state}{name}
> |5665|3:3|reload| computer_state_name = reload
>
> |5665|3:3|reload| ---- WARNING ----
> |5665|3:3|reload| 2010-03-24
> 17:38:22|5665|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}
> |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> |5665|3:3|reload| (-1) DataStructure.pm, _automethod (line: 675)
> |5665|3:3|reload| (-2) Autoload.pm, __ANON__ (line: 80)
> |5665|3:3|reload| (-3) new.pm, computer_not_being_used (line: 750)
> |5665|3:3|reload| (-4) new.pm, process (line: 170)
> |5665|3:3|reload| (-5) vcld, make_new_child (line: 594)
> |5665|3:3|reload| (-6) vcld, main (line: 341)
>
>
> |5665|3:3|reload| ---- WARNING ----
> |5665|3:3|reload| 2010-03-24
> 17:38:22|5665|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}
> |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> |5665|3:3|reload| (-1) DataStructure.pm, _automethod (line: 675)
> |5665|3:3|reload| (-2) Autoload.pm, __ANON__ (line: 80)
> |5665|3:3|reload| (-3) new.pm, computer_not_being_used (line: 751)
> |5665|3:3|reload| (-4) new.pm, process (line: 170)
> |5665|3:3|reload| (-5) vcld, make_new_child (line: 594)
> |5665|3:3|reload| (-6) vcld, main (line: 341)
>
> 2010-03-24 17:38:22|5665|3:3|reload|utils.pm:get_management_node_id(9364)|environment
> variable: 1
> 2010-03-24 17:38:22|5665|3:3|reload|new.pm:computer_not_being_used(788)|esx3-basewinxp-v0
> state is reload
> 2010-03-24 17:38:22|5665|3:3|reload|new.pm:computer_not_being_used(798)|esx3-basewinxp-v0
> is available, its state is reload
> 2010-03-24 17:38:22|5665|3:3|reload|new.pm:process(170)|esx3-basewinxp-v0
> is not being used
> 2010-03-24
> 17:38:22|5665|3:3|reload|DataStructure.pm:is_parent_reservation(854)|returning
> true: parent reservation ID for this request: 3
> 2010-03-24
> 17:38:22|5665|3:3|reload|DataStructure.pm:get_computer_state_name(1946)|attempting
> to retrieve current state of computer esx3-basewinxp-v0 from the database
> 2010-03-24
> 17:38:22|5665|3:3|reload|DataStructure.pm:get_computer_state_name(1977)|retrieved
> current state of computer esx3-basewinxp-v0 from the database: reload
> 2010-03-24 17:38:22|5665|3:3|reload|DataStructure.pm:_automethod(697)|data
> structure updated:
> $self->request_data->{reservation}{3}{computer}{state}{name}
> |5665|3:3|reload| computer_state_name = reload
>
> |5665|3:3|reload| ---- WARNING ----
> |5665|3:3|reload| 2010-03-24
> 17:38:22|5665|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}
> |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> |5665|3:3|reload| (-1) DataStructure.pm, _automethod (line: 675)
> |5665|3:3|reload| (-2) Autoload.pm, __ANON__ (line: 80)
> |5665|3:3|reload| (-3) new.pm, reload_image (line: 480)
> |5665|3:3|reload| (-4) new.pm, process (line: 266)
> |5665|3:3|reload| (-5) vcld, make_new_child (line: 594)
> |5665|3:3|reload| (-6) vcld, main (line: 341)
>
>
> |5665|3:3|reload| ---- WARNING ----
> |5665|3:3|reload| 2010-03-24
> 17:38:22|5665|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}
> |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> |5665|3:3|reload| (-1) DataStructure.pm, _automethod (line: 675)
> |5665|3:3|reload| (-2) Autoload.pm, __ANON__ (line: 80)
> |5665|3:3|reload| (-3) new.pm, reload_image (line: 481)
> |5665|3:3|reload| (-4) new.pm, process (line: 266)
> |5665|3:3|reload| (-5) vcld, make_new_child (line: 594)
> |5665|3:3|reload| (-6) vcld, main (line: 341)
>
> 2010-03-24 17:38:22|5665|3:3|reload|utils.pm:get_management_node_id(9364)|environment
> variable: 1
> 2010-03-24 17:38:22|5665|3:3|reload|new.pm:reload_image(514)|calling
> VCL::Module::Provisioning::esx->node_status()
> 2010-03-24 17:38:22|5665|3:3|reload|utils.pm:insertloadlog(4710)|inserted
> computer=3, statuscheck, checking status of node
> 2010-03-24 17:38:22|5665|3:3|reload|esx.pm:node_status(787)|Entering
> node_status, checking status of esx3-basewinxp-v0
> 2010-03-24 17:38:22|5665|3:3|reload|esx.pm:node_status(788)|request_for_imaging:
> 0
> 2010-03-24 17:38:22|5665|3:3|reload|esx.pm:node_status(789)|requeseted
> image name: esx3-basewinxp-v0
> 2010-03-24 17:38:22|5665|3:3|reload|esx.pm:node_status(819)|checking if
> esx3-basewinxp-v0 is pingable
> 2010-03-24 17:38:23|5665|3:3|reload|esx.pm:node_status(825)|esx3-basewinxp-v0
> is not pingable (0)
> 2010-03-24 17:38:23|5665|3:3|reload|new.pm:reload_image(560)|node_status
> returned a scalar: RELOAD
> 2010-03-24 17:38:23|5665|3:3|reload|new.pm:reload_image(576)|request state
> is reload, node will be reloaded regardless of status
> 2010-03-24 17:38:23|5665|3:3|reload|new.pm:reload_image(602)|node status
> is reload, esx3-basewinxp-v0 will be reloaded
> 2010-03-24 17:38:23|5665|3:3|reload|utils.pm:insertloadlog(4710)|inserted
> computer=3, loadimageblade, esx3-basewinxp-v0 must be reloaded with
> esx3-basewinxp-v0
> 2010-03-24 17:38:23|5665|3:3|reload|new.pm:reload_image(616)|calling
> VCL::Module::Provisioning::esx->does_image_exist()
> 2010-03-24 17:38:23|5665|3:3|reload|utils.pm:run_ssh_command(6180)|executing
> SSH command on 192.168.129.37:
> |5665|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-24 17:38:23|5665|3:3|reload|utils.pm:run_ssh_command(6262)|run_ssh_command
> output:
> |5665|3:3|reload| esx3-basewinxp-v0
> 2010-03-24 17:38:23|5665|3:3|reload|utils.pm:run_ssh_command(6276)|SSH
> command executed on 192.168.129.37, returning (0, "esx3-basewinxp-v0")
> 2010-03-24 17:38:23|5665|3:3|reload|esx.pm:does_image_exist(917)|image
> esx3-basewinxp-v0 exists
> 2010-03-24 17:38:23|5665|3:3|reload|new.pm:reload_image(619)|esx3-basewinxp-v0
> exists on this management node
> 2010-03-24 17:38:23|5665|3:3|reload|utils.pm:insertloadlog(4710)|inserted
> computer=3, doesimageexists, confirmed image exists
> 2010-03-24 17:38:23|5665|3:3|reload|utils.pm:update_computer_state(2228)|computer
> 3 state updated to: reloading
> 2010-03-24 17:38:23|5665|3:3|reload|new.pm:reload_image(652)|computer
> esx3-basewinxp-v0 state set to reloading
> 2010-03-24 17:38:23|5665|3:3|reload|utils.pm:insertloadlog(4710)|inserted
> computer=3, info, computer state updated to reloading
> 2010-03-24 17:38:23|5665|3:3|reload|new.pm:reload_image(663)|calling
> VCL::Module::Provisioning::esx->load() subroutine
> 2010-03-24 17:38:23|5665|3:3|reload|utils.pm:insertloadlog(4710)|inserted
> computer=3, info, calling VCL::Module::Provisioning::esx->load() subroutine
> 2010-03-24 17:38:23|5665|3:3|reload|esx.pm:
> load(165)|****************************************************
>
> |5665|3:3|reload| ---- WARNING ----
> |5665|3:3|reload| 2010-03-24
> 17:38:23|5665|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}
> |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> |5665|3:3|reload| (-1) DataStructure.pm, _automethod (line: 675)
> |5665|3:3|reload| (-2) Autoload.pm, __ANON__ (line: 80)
> |5665|3:3|reload| (-3) esx.pm, load (line: 181)
> |5665|3:3|reload| (-4) new.pm, reload_image (line: 665)
> |5665|3:3|reload| (-5) new.pm, process (line: 266)
> |5665|3:3|reload| (-6) vcld, make_new_child (line: 594)
>
>
> |5665|3:3|reload| ---- WARNING ----
> |5665|3:3|reload| 2010-03-24
> 17:38:23|5665|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}
> |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> |5665|3:3|reload| (-1) DataStructure.pm, _automethod (line: 675)
> |5665|3:3|reload| (-2) Autoload.pm, __ANON__ (line: 80)
> |5665|3:3|reload| (-3) esx.pm, load (line: 182)
> |5665|3:3|reload| (-4) new.pm, reload_image (line: 665)
> |5665|3:3|reload| (-5) new.pm, process (line: 266)
> |5665|3:3|reload| (-6) vcld, make_new_child (line: 594)
>
> 2010-03-24 17:38:23|5665|3:3|reload|esx.pm:load(193)|Calling
> get_vmware_host_info
> No recipient addresses found in header
> 2010-03-24 17:38:26|5665|3:3|reload|utils.pm:mail(1348)|SUCCESS -- Sending
> mail To: , PROBLEM -- esx.pm
>
> |5665|3:3|reload| ---- CRITICAL ----
> |5665|3:3|reload| 2010-03-24 17:38:23|5665|3:3|reload|esx.pm:get_vmware_host_info(1012)|AMIT
> DEBUGGING: esx35-hypervisor-1.odu.edu
> |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> |5665|3:3|reload| (-1) esx.pm, get_vmware_host_info (line: 1012)
> |5665|3:3|reload| (-2) esx.pm, load (line: 194)
> |5665|3:3|reload| (-3) new.pm, reload_image (line: 665)
> |5665|3:3|reload| (-4) new.pm, process (line: 266)
> |5665|3:3|reload| (-5) vcld, make_new_child (line: 594)
> |5665|3:3|reload| (-6) vcld, main (line: 341)
>
> 2010-03-24 17:38:27|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:38:27
> 2010-03-24 17:38:29|5665|3:3|reload|esx.pm:get_vmware_host_info(1019)|host
> info output for esx35-hypervisor-1
> |5665|3:3|reload| Host Information
> |5665|3:3|reload| Host Name: esx35-hypervisor-1.odu.edu
> 2010-03-24 17:38:29|5665|3:3|reload|esx.pm:get_vmware_host_info(1025)|found
> hostname_value= esx35-hypervisor-1.odu.edu
> 2010-03-24 17:38:29|5665|3:3|reload|esx.pm:load(197)|Collected
> esx35-hypervisor-1.odu.edu for vmware host name
> 2010-03-24 17:38:29|5665|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-24 17:38:29|5665|3:3|reload|esx.pm:load(211)|Entered ESX module,
> loading esx3-basewinxp-v0 on esx3-basewinxp-v0 (on
> esx35-hypervisor-1.odu.edu) for reservation 3
> 2010-03-24 17:38:29|5665|3:3|reload|esx.pm:load(212)|Datastore:
> 192.168.129.37:/install/image/vmware_images
> 2010-03-24 17:38:29|5665|3:3|reload|esx.pm:load(223)|VM info command:
> /usr/lib/vmware-vcli/apps/vm/vminfo.pl --server 'esx35-hypervisor-1'
> --vmname esx3-basewinxp-v0 --username root --password 'xxxxxxxxxxx'
> 2010-03-24 17:38:30|5665|3:3|reload|esx.pm:load(226)|VM info output:
> |5665|3:3|reload| Information of Virtual Machine esx3-basewinxp-v0
> |5665|3:3|reload| Name: esx3-basewinxp-v0
> |5665|3:3|reload| No. of CPU(s): 2
> |5665|3:3|reload| Memory Size: 512
> |5665|3:3|reload| Virtual Disks: 1
> |5665|3:3|reload| Template: 0
> |5665|3:3|reload| vmPathName: [localstore]
> esx3-basewinxp-v0/esx3-basewinxp-v0.vmx
> |5665|3:3|reload| Guest OS: Not Known
> |5665|3:3|reload| guestId: Not Known
> |5665|3:3|reload| Host name: Not Known
> |5665|3:3|reload| IP Address: Not Known
> |5665|3:3|reload| VMware Tools: VMware Tools is not running.
> |5665|3:3|reload| Cpu usage: Not Known
> |5665|3:3|reload| Host memory usage: Not Known
> |5665|3:3|reload| Guest memory usage: Not Known
> |5665|3:3|reload| Overall Status: The entity is OK
> 2010-03-24 17:38:30|5665|3:3|reload|esx.pm:load(237)|Power off command:
> /usr/lib/vmware-vcli/apps/vm/vmcontrol.pl --server 'esx35-hypervisor-1'
> --vmname esx3-basewinxp-v0 --operation poweroff --username root --password
> 'xxxxxxxxxxx'
> 2010-03-24 17:38:32|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:38:32
> 2010-03-24 17:38:32|5665|3:3|reload|esx.pm:load(240)|Powered off:
> |5665|3:3|reload| Error in 'esx3-basewinxp-v0' under host
> esx35-hypervisor-1.odu.edu: The attempted operation cannot be performed in
> the current state
> 2010-03-24 17:38:32|5665|3:3|reload|esx.pm:load(253)|Un-Register Command:
> /usr/lib/vmware-vcli/apps/vm/vmregister.pl --server 'esx35-hypervisor-1'
> --username root --password 'xxxxxxxxxxx' --vmxpath
> '[VCL]/inuse/esx3-basewinxp-v0/esx3-basewinxp-v0.vmx' --operation unregister
> --vmname esx3-basewinxp-v0 --pool Resources --hostname '
> esx35-hypervisor-1.odu.edu' --datacenter 'ha-datacenter'
> 2010-03-24 17:38:35|5665|3:3|reload|esx.pm:load(256)|Un-Registered:
> |5665|3:3|reload| Unregister of VM 'esx3-basewinxp-v0' successfully
> completed under host esx35-hypervisor-1.odu.edu
> 2010-03-24 17:38:35|5665|3:3|reload|utils.pm:run_ssh_command(6180)|executing
> SSH command on 192.168.129.37:
> |5665|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/esx3-basewinxp-v0'
> 2>&1
> 2010-03-24 17:38:36|5665|3:3|reload|utils.pm:run_ssh_command(6262)|run_ssh_command
> output:
> |5665|3:3|reload| none
> 2010-03-24 17:38:36|5665|3:3|reload|utils.pm:run_ssh_command(6276)|SSH
> command executed on 192.168.129.37, returning (0, "none")
> 2010-03-24 17:38:36|5665|3:3|reload|esx.pm:load(262)|Removed old vm folder
> 2010-03-24 17:38:36|5665|3:3|reload|utils.pm:run_ssh_command(6180)|executing
> SSH command on 192.168.129.37:
> |5665|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/esx3-basewinxp-v0'
> 2>&1
> 2010-03-24 17:38:36|5665|3:3|reload|utils.pm:run_ssh_command(6262)|run_ssh_command
> output:
> |5665|3:3|reload| none
> 2010-03-24 17:38:36|5665|3:3|reload|utils.pm:run_ssh_command(6276)|SSH
> command executed on 192.168.129.37, returning (0, "none")
> 2010-03-24 17:38:36|5665|3:3|reload|utils.pm:run_ssh_command(6180)|executing
> SSH command on 192.168.129.37:
> |5665|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/esx3-basewinxp-v0/esx3-basewinxp-v0.vmdk'
> 2>&1
> 2010-03-24 17:38:36|5665|3:3|reload|utils.pm:run_ssh_command(6262)|run_ssh_command
> output:
> |5665|3:3|reload| none
> 2010-03-24 17:38:36|5665|3:3|reload|utils.pm:run_ssh_command(6276)|SSH
> command executed on 192.168.129.37, returning (0, "none")
> 2010-03-24 17:38:36|5665|3:3|reload|esx.pm:load(278)|COPIED VMDK
> SUCCESSFULLY
> 2010-03-24 17:38:36|5665|3:3|reload|utils.pm:run_ssh_command(6180)|executing
> SSH command on 192.168.129.37:
> |5665|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/esx3-basewinxp-v0/esx3-basewinxp-v0-flat.vmdk'
> 2>&1
> 2010-03-24 17:38:37|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:38:37
> 2010-03-24 17:38:42|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:38:42
> 2010-03-24 17:38:47|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:38:47
> 2010-03-24 17:38:52|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:38:52
> 2010-03-24 17:38:57|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:38:57
> 2010-03-24 17:39:02|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:39:02
> 2010-03-24 17:39:07|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:39:07
> 2010-03-24 17:39:12|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:39:12
> 2010-03-24 17:39:18|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:39:17
> 2010-03-24 17:39:23|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:39:23
> 2010-03-24 17:39:28|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:39:28
> 2010-03-24 17:39:28|5665|3:3|reload|utils.pm:run_ssh_command(6262)|run_ssh_command
> output:
> |5665|3:3|reload| none
> 2010-03-24 17:39:28|5665|3:3|reload|utils.pm:run_ssh_command(6276)|SSH
> command executed on 192.168.129.37, returning (0, "none")
> 2010-03-24 17:39:28|5665|3:3|reload|utils.pm:run_ssh_command(6180)|executing
> SSH command on 192.168.129.37:
> |5665|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/esx3-basewinxp-v0/esx3-basewinxp-v0.vmdk
> 2>&1' 2>&1
> 2010-03-24 17:39:29|5665|3:3|reload|utils.pm:run_ssh_command(6262)|run_ssh_command
> output:
> |5665|3:3|reload| ddb.adapterType = "buslogic"
> 2010-03-24 17:39:29|5665|3:3|reload|utils.pm:run_ssh_command(6276)|SSH
> command executed on 192.168.129.37, returning (0, "ddb.adapterType =
> "buslogic"")
> 2010-03-24 17:39:29|5665|3:3|reload|esx.pm:load(311)|adapter= buslogic
> 2010-03-24 17:39:29|5665|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.
>
>
> |5665|3:3|reload| ---- WARNING ----
> |5665|3:3|reload| 2010-03-24
> 17:39:29|5665|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.
> |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> |5665|3:3|reload| (-1) vcld, warning_handler (line: 636)
> |5665|3:3|reload| (-2) esx.pm, load (line: 343)
> |5665|3:3|reload| (-3) new.pm, reload_image (line: 665)
> |5665|3:3|reload| (-4) new.pm, process (line: 266)
> |5665|3:3|reload| (-5) vcld, make_new_child (line: 594)
> |5665|3:3|reload| (-6) vcld, main (line: 341)
>
>
> |5665|3:3|reload| ---- WARNING ----
> |5665|3:3|reload| 2010-03-24
> 17:39:29|5665|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.
> |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> |5665|3:3|reload| (-1) vcld, warning_handler (line: 636)
> |5665|3:3|reload| (-2) esx.pm, load (line: 353)
> |5665|3:3|reload| (-3) new.pm, reload_image (line: 665)
> |5665|3:3|reload| (-4) new.pm, process (line: 266)
> |5665|3:3|reload| (-5) vcld, make_new_child (line: 594)
> |5665|3:3|reload| (-6) vcld, main (line: 341)
>
> 2010-03-24 17:39:29|5665|3:3|reload|esx.pm:load(353)|eth1 MAC address set
> for vcl assigned
>
> |5665|3:3|reload| ---- WARNING ----
> |5665|3:3|reload| 2010-03-24
> 17:39:29|5665|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.
> |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> |5665|3:3|reload| (-1) vcld, warning_handler (line: 636)
> |5665|3:3|reload| (-2) esx.pm, load (line: 354)
> |5665|3:3|reload| (-3) new.pm, reload_image (line: 665)
> |5665|3:3|reload| (-4) new.pm, process (line: 266)
> |5665|3:3|reload| (-5) vcld, make_new_child (line: 594)
> |5665|3:3|reload| (-6) vcld, main (line: 341)
>
> 2010-03-24 17:39:29|5665|3:3|reload|esx.pm:load(376)|wrote vmxarray to
> /tmp/esx3-basewinxp-v0.vmx
> 2010-03-24 17:39:29|5665|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/esx3-basewinxp-v0.vmx 192.168.129.37:/install/image/vmware_images/inuse/esx3-basewinxp-v0/esx3-basewinxp-v0.vmx
> 2>&1
> 2010-03-24 17:39:29|5665|3:3|reload|utils.pm:run_scp_command(6453)|scp
> successful: attempt 1/3, exit status: 0, output: none
> 2010-03-24 17:39:29|5665|3:3|reload|esx.pm:load(401)|Register Command:
> /usr/lib/vmware-vcli/apps/vm/vmregister.pl --server 'esx35-hypervisor-1'
> --username root --password 'xxxxxxxxxxx' --vmxpath
> '[VCL]/inuse/esx3-basewinxp-v0/esx3-basewinxp-v0.vmx' --operation register
> --vmname esx3-basewinxp-v0 --pool Resources --hostname '
> esx35-hypervisor-1.odu.edu' --datacenter 'ha-datacenter'
> 2010-03-24 17:39:33|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:39:33
> 2010-03-24 17:39:38|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:39:38
> 2010-03-24 17:39:43|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:39:43
> 2010-03-24 17:39:48|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:39:48
> 2010-03-24 17:39:53|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:39:53
> 2010-03-24 17:39:58|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:39:58
> 2010-03-24 17:40:03|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:40:03
> 2010-03-24 17:40:08|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:40:08
> 2010-03-24 17:40:13|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:40:13
> 2010-03-24 17:40:18|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:40:18
> 2010-03-24 17:40:23|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:40:23
> 2010-03-24 17:40:28|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:40:28
> 2010-03-24 17:40:32|5665|3:3|reload|esx.pm:load(404)|Registered:
> |5665|3:3|reload| Register of VM 'esx3-basewinxp-v0' successfully completed
> under host esx35-hypervisor-1.odu.edu
> 2010-03-24 17:40:32|5665|3:3|reload|esx.pm:load(413)|Power on command:
> /usr/lib/vmware-vcli/apps/vm/vmcontrol.pl --server 'esx35-hypervisor-1'
> --vmname esx3-basewinxp-v0 --operation poweron --username root --password
> 'xxxxxxxxxxx'
> 2010-03-24 17:40:33|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:40:33
> 2010-03-24 17:40:33|5665|3:3|reload|esx.pm:load(416)|Powered on: Virtual
> Machine esx3-basewinxp-v0 not found.
> 2010-03-24 17:40:33|5665|3:3|reload|esx.pm:load(505)|IP is known for
> esx3-basewinxp-v0
> 2010-03-24 17:40:33|5665|3:3|reload|esx.pm:load(511)|Waiting for ssh to
> come up on esx3-basewinxp-v0
> 2010-03-24 17:40:34|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 1
> 2010-03-24 17:40:38|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:40:38
> 2010-03-24 17:40:40|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 2
> 2010-03-24 17:40:43|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:40:43
> 2010-03-24 17:40:46|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 3
> 2010-03-24 17:40:48|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:40:48
> 2010-03-24 17:40:52|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 4
> 2010-03-24 17:40:53|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:40:53
> 2010-03-24 17:40:58|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:40:58
> 2010-03-24 17:40:58|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 5
> 2010-03-24 17:41:03|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:41:03
> 2010-03-24 17:41:04|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 6
> 2010-03-24 17:41:08|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:41:08
> 2010-03-24 17:41:10|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 7
> 2010-03-24 17:41:13|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:41:13
> 2010-03-24 17:41:16|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 8
> 2010-03-24 17:41:18|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:41:18
> 2010-03-24 17:41:22|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 9
> 2010-03-24 17:41:23|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:41:23
> 2010-03-24 17:41:28|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:41:28
> 2010-03-24 17:41:28|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 10
> 2010-03-24 17:41:33|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:41:33
> 2010-03-24 17:41:34|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 11
> 2010-03-24 17:41:38|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:41:38
> 2010-03-24 17:41:41|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 12
> 2010-03-24 17:41:43|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:41:43
> 2010-03-24 17:41:47|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 13
> 2010-03-24 17:41:49|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:41:48
> 2010-03-24 17:41:53|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 14
> 2010-03-24 17:41:54|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:41:54
> 2010-03-24 17:41:59|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:41:59
> 2010-03-24 17:41:59|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 15
> 2010-03-24 17:42:04|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:42:04
> 2010-03-24 17:42:05|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 16
> 2010-03-24 17:42:09|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:42:09
> 2010-03-24 17:42:11|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 17
> 2010-03-24 17:42:14|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:42:14
> 2010-03-24 17:42:17|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 18
> 2010-03-24 17:42:19|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:42:19
> 2010-03-24 17:42:23|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 19
> 2010-03-24 17:42:24|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:42:24
> 2010-03-24 17:42:29|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 20
> 2010-03-24 17:42:29|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:42:29
> 2010-03-24 17:42:34|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:42:34
> 2010-03-24 17:42:35|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 21
> 2010-03-24 17:42:39|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:42:39
> 2010-03-24 17:42:41|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 22
> 2010-03-24 17:42:44|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:42:44
> 2010-03-24 17:42:47|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 23
> 2010-03-24 17:42:49|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:42:49
> 2010-03-24 17:42:53|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 24
> 2010-03-24 17:42:54|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:42:54
> 2010-03-24 17:42:59|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 25
> 2010-03-24 17:42:59|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:42:59
> 2010-03-24 17:43:04|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:43:04
> 2010-03-24 17:43:05|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 26
> 2010-03-24 17:43:09|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:43:09
> 2010-03-24 17:43:11|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 27
> 2010-03-24 17:43:14|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:43:14
> 2010-03-24 17:43:17|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 28
> 2010-03-24 17:43:19|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:43:19
> 2010-03-24 17:43:23|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 29
> 2010-03-24 17:43:24|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:43:24
> 2010-03-24 17:43:29|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 30
> 2010-03-24 17:43:29|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:43:29
> 2010-03-24 17:43:34|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:43:34
> 2010-03-24 17:43:35|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 31
> 2010-03-24 17:43:39|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:43:39
> 2010-03-24 17:43:41|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 32
> 2010-03-24 17:43:44|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:43:44
> 2010-03-24 17:43:47|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 33
> 2010-03-24 17:43:49|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:43:49
> 2010-03-24 17:43:53|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 34
> 2010-03-24 17:43:54|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:43:54
> 2010-03-24 17:43:59|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 35
> 2010-03-24 17:43:59|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:43:59
> 2010-03-24 17:44:04|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:44:04
> 2010-03-24 17:44:05|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 36
> 2010-03-24 17:44:09|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:44:09
> 2010-03-24 17:44:11|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 37
> 2010-03-24 17:44:14|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:44:14
> 2010-03-24 17:44:17|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 38
> 2010-03-24 17:44:19|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:44:19
> 2010-03-24 17:44:23|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 39
> 2010-03-24 17:44:24|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:44:24
> 2010-03-24 17:44:29|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 40
> 2010-03-24 17:44:29|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:44:29
> 2010-03-24 17:44:35|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:44:34
> 2010-03-24 17:44:35|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 41
> 2010-03-24 17:44:40|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:44:40
> 2010-03-24 17:44:41|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 42
> 2010-03-24 17:44:45|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:44:45
> 2010-03-24 17:44:47|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 43
> 2010-03-24 17:44:50|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:44:50
> 2010-03-24 17:44:53|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 44
> 2010-03-24 17:44:55|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:44:55
> 2010-03-24 17:44:59|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 45
> 2010-03-24 17:45:00|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:45:00
> 2010-03-24 17:45:05|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:45:05
> 2010-03-24 17:45:05|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 46
> 2010-03-24 17:45:10|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:45:10
> 2010-03-24 17:45:11|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 47
> 2010-03-24 17:45:15|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:45:15
> 2010-03-24 17:45:17|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 48
> 2010-03-24 17:45:20|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:45:20
> 2010-03-24 17:45:23|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 49
> 2010-03-24 17:45:25|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:45:25
> 2010-03-24 17:45:29|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 50
> 2010-03-24 17:45:30|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:45:30
> 2010-03-24 17:45:35|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:45:35
> 2010-03-24 17:45:35|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> seconds, waiting for computer to start SSH. Try 51
> 2010-03-24 17:45:40|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:45:40
> No recipient addresses found in header
> 2010-03-24 17:45:45|5665|3:3|reload|utils.pm:mail(1348)|SUCCESS -- Sending
> mail To: , PROBLEM -- esx.pm
>
> |5665|3:3|reload| ---- CRITICAL ----
> |5665|3:3|reload| 2010-03-24 17:45:41|5665|3:3|reload|esx.pm:load(521)|waited
> acceptable amount of time for sshd to become active, please check
> esx3-basewinxp-v0 on esx35-hypervisor-1
> |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> |5665|3:3|reload| (-1) esx.pm, load (line: 521)
> |5665|3:3|reload| (-2) new.pm, reload_image (line: 665)
> |5665|3:3|reload| (-3) new.pm, process (line: 266)
> |5665|3:3|reload| (-4) vcld, make_new_child (line: 594)
> |5665|3:3|reload| (-5) vcld, main (line: 341)
>
>
> |5665|3:3|reload| ---- WARNING ----
> |5665|3:3|reload| 2010-03-24 17:45:45|5665|3:3|reload|new.pm:reload_image(670)|esx3-basewinxp-v0
> failed to load on esx3-basewinxp-v0, returning
> |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> |5665|3:3|reload| (-1) new.pm, reload_image (line: 670)
> |5665|3:3|reload| (-2) new.pm, process (line: 266)
> |5665|3:3|reload| (-3) vcld, make_new_child (line: 594)
> |5665|3:3|reload| (-4) vcld, main (line: 341)
>
> 2010-03-24 17:45:45|5665|3:3|reload|utils.pm:insertloadlog(4710)|inserted
> computer=3, loadimagefailed, esx3-basewinxp-v0 failed to load on
> esx3-basewinxp-v0
>
> |5665|3:3|reload| ---- WARNING ----
> |5665|3:3|reload| 2010-03-24 17:45:45|5665|3:3|reload|new.pm:process(313)|failed
> to load esx3-basewinxp-v0 with esx3-basewinxp-v0
> |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> |5665|3:3|reload| (-1) new.pm, process (line: 313)
> |5665|3:3|reload| (-2) vcld, make_new_child (line: 594)
> |5665|3:3|reload| (-3) vcld, main (line: 341)
>
> 2010-03-24
> 17:45:45|5665|3:3|reload|DataStructure.pm:get_computer_state_name(1946)|attempting
> to retrieve current state of computer esx3-basewinxp-v0 from the database
> 2010-03-24
> 17:45:45|5665|3:3|reload|DataStructure.pm:get_computer_state_name(1977)|retrieved
> current state of computer esx3-basewinxp-v0 from the database: reloading
> 2010-03-24 17:45:45|5665|3:3|reload|DataStructure.pm:_automethod(697)|data
> structure updated:
> $self->request_data->{reservation}{3}{computer}{state}{name}
> |5665|3:3|reload| computer_state_name = reloading
> No recipient addresses found in header
> 2010-03-24 17:45:45|5665|3:3|reload|utils.pm:mail(1348)|SUCCESS -- Sending
> mail To: , PROBLEM -- State.pm
>
> |5665|3:3|reload| ---- CRITICAL ----
> |5665|3:3|reload| 2010-03-24
> 17:45:45|5665|3:3|reload|State.pm:reservation_failed(290)|reservation failed
> on esx3-basewinxp-v0: process failed after trying to load or make available
> |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> |5665|3:3|reload| (-1) State.pm, reservation_failed (line: 290)
> |5665|3:3|reload| (-2) new.pm, process (line: 316)
> |5665|3:3|reload| (-3) vcld, make_new_child (line: 594)
> |5665|3:3|reload| (-4) vcld, main (line: 341)
>
> 2010-03-24 17:45:45|5665|3:3|reload|utils.pm:insertloadlog(4710)|inserted
> computer=3, failed, process failed after trying to load or make available
> 2010-03-24
> 17:45:45|5665|3:3|reload|State.pm:reservation_failed(293)|inserted
> computerloadlog entry
> 2010-03-24 17:45:45|5665|3:3|reload|utils.pm:update_computer_state(2228)|computer
> 3 state updated to: failed
> 2010-03-24
> 17:45:45|5665|3:3|reload|State.pm:reservation_failed(312)|computer
> esx3-basewinxp-v0 (3) state set to failed
> 2010-03-24 17:45:45|5665|3:3|reload|utils.pm:update_request_state(2186)|request
> 3 state updated to: failed, laststate to: image
> 2010-03-24 17:45:45|5665|3:3|reload|State.pm:reservation_failed(325)|set
> request state to 'failed'/'image'
> 2010-03-24 17:45:45|5665|3:3|reload|utils.pm:is_inblockrequest(6972)|zero
> rows were returned from database select
> 2010-03-24
> 17:45:45|5665|3:3|reload|State.pm:reservation_failed(343)|esx3-basewinxp-v0
> is NOT in blockcomputers table
> 2010-03-24
> 17:45:45|5665|3:3|reload|State.pm:reservation_failed(346)|exiting 1
> 2010-03-24 17:45:45|5665|3:3|reload|State.pm:DESTROY(905)|destructor
> called, ref($self)=VCL::new
> 2010-03-24 17:45:45|5665|3:3|reload|utils.pm:delete_computerloadlog_reservation(7551)|removing
> computerloadlog entries matching loadstate = begin
> 2010-03-24 17:45:45|5665|3:3|reload|utils.pm:delete_computerloadlog_reservation(7598)|deleted
> rows from computerloadlog for reservation id=3
> 2010-03-24 17:45:45|5665|3:3|reload|State.pm:DESTROY(912)|removed
> computerloadlog rows with loadstate=begin for reservation
> 2010-03-24 17:45:45|5665|3:3|reload|State.pm:DESTROY(924)|number of
> database handles state process created: 1
> 2010-03-24 17:45:45|5665|3:3|reload|State.pm:DESTROY(933)|process has a
> database handle stored in $ENV{dbh}, attempting disconnect
> 2010-03-24 17:45:45|5665|3:3|reload|State.pm:DESTROY(935)|$ENV{dbh}:
> database disconnect successful
> 2010-03-24 17:45:45|5665|3:3|reload|State.pm:DESTROY(949)|VCL::new process
> 5665 exiting
> 2010-03-24 17:45:45|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:45:45
> 2010-03-24 17:45:45|5443|3:3|failed|vcld:main(250)|request deleted
> 2010-03-24 17:45:45|5443|vcld:REAPER(744)|VCL process exited for
> reservation 3
> 2010-03-24 17:45:45|5443|vcld:main(165)|lastcheckin time updated for
> management node 1: 2010-03-24 17:45:45
>
>
> Thank you,
> Amit
>
>
Re: Reloading VM After Image Capture and VM Registration: FAILS
Posted by Ryan Johnson <rj...@gwmail.gwu.edu>.
I have completed an installation with the free license, but it seems that
the info for the mounts can become stale and I believe unless you have
backup scripts in place, you will always have to remount after a restart.
On Mon, Apr 5, 2010 at 10:32 PM, Jeffrey Wisman
<je...@csueastbay.edu>wrote:
> Were you ever able to resolve this issue? It sounds an awful lot like our
> problem. We were advised to purchase the VMWare license, but outside of
> doing that, I'm at a loss as to what to do.
>
> Thanks,
> Jeff
>
>
> On Wed, Mar 24, 2010 at 3:02 PM, Kumar, Amit H. <AH...@odu.edu> wrote:
>
> > HI All ....
> >
> > I am close to getting this first step done. After the Image capture and
> VM
> > registration with the VMhost it fails to power on the VMmachine. Also I
> > notice that the VM registered on ESXi VMhost shows up as "Unknown
> (invalid)"
> >
> > Not sure what went wrong:
> >
> > Please advise:
> >
> > 2010-03-24 17:35:11|5443|2:2|image|vcld:main(276)|reservation 2 is NOT
> > already being processed
> >
> > |5443|2:2|image| ---- WARNING ----
> > |5443|2:2|image| 2010-03-24 17:35:12|5443|2:2|image|utils.pm:
> get_request_info(5218)|preferredimageid
> > is not set for computer id=3
> > |5443|2:2|image| ( 0) utils.pm, notify (line: 737)
> > |5443|2:2|image| (-1) utils.pm, get_request_info (line: 5218)
> > |5443|2:2|image| (-2) vcld, main (line: 280)
> >
> > 2010-03-24 17:35:12|5443|2:2|image|utils.pm:
> get_request_info(5354)|standalone
> > affiliation found: Local
> > 2010-03-24 17:35:12|5443|2:2|image|utils.pm:
> get_management_node_info(6815)|management
> > node info retrieved from database for colbert
> > 2010-03-24 17:35:12|5443|2:2|image|vcld:main(281)|retrieved request
> > information from database
> > 2010-03-24 17:35:12|5443|2:2|image|utils.pm:
> get_management_node_info(6815)|management
> > node info retrieved from database for colbert
> > 2010-03-24
> >
> 17:35:12|5443|2:2|image|DataStructure.pm:is_parent_reservation(854)|returning
> > true: parent reservation ID for this request: 2
> > 2010-03-24 17:35:12|5443|2:2|image|utils.pm:
> update_request_state(2186)|request
> > 2 state updated to: pending, laststate to: image
> > 2010-03-24 17:35:12|5443|2:2|image|utils.pm:insertloadlog(4710)|inserted
> > computer=3, begin, beginning to process, state is image
> > 2010-03-24 17:35:12|5443|2:2|image|vcld:make_new_child(509)|loaded
> > VCL::image module
> > 2010-03-24 17:35:12|5445|2:2|image|vcld:make_new_child(582)|vcld
> > environment variable set to 0 for this process
> > 2010-03-24 17:35:12|5445|2:2|image|Module.pm:new(132)|constructor called,
> > class=VCL::image
> > 2010-03-24 17:35:12|5445|2:2|image|Module.pm:new(154)|VCL::image object
> > created
> > 2010-03-24 17:35:12|5443|2:2|image|vcld:make_new_child(566)|current
> number
> > of forked kids: 1
> > 2010-03-24 17:35:12|5445|2:2|image|State.pm:initialize(85)|obtained a
> > database handle for this state process, stored as $ENV{dbh}
> > 2010-03-24 17:35:12|5445|2:2|image|State.pm:check_image_os(839)|no
> > corrections need to be made to image OS: esx35
> > 2010-03-24
> >
> 17:35:12|5445|2:2|image|DataStructure.pm:is_parent_reservation(854)|returning
> > true: parent reservation ID for this request: 2
> > 2010-03-24 17:35:12|5445|2:2|image|utils.pm:
> rename_vcld_process(7863)|reservation
> > count: 1
> > 2010-03-24 17:35:12|5445|2:2|image|utils.pm:
> rename_vcld_process(7882)|PARENTIMAGE:
> > 1
> > 2010-03-24 17:35:12|5445|2:2|image|utils.pm:
> rename_vcld_process(7883)|SUBIMAGE:
> > 0
> > 2010-03-24 17:35:12|5445|2:2|image|utils.pm:
> rename_vcld_process(7901)|renamed
> > process to 'vcld VCL::image 2:2 image imaging'
> > 2010-03-24
> >
> 17:35:12|5445|2:2|image|DataStructure.pm:is_parent_reservation(854)|returning
> > true: parent reservation ID for this request: 2
> > 2010-03-24
> >
> 17:35:12|5445|2:2|image|DataStructure.pm:is_parent_reservation(854)|returning
> > true: parent reservation ID for this request: 2
> > 2010-03-24 17:35:12|5445|2:2|image|State.pm:initialize(121)|attempting to
> > load provisioning module: VCL::Module::Provisioning::esx
> > 2010-03-24 17:35:12|5445|2:2|image|esx.pm:initialize(138)|esx vmware
> > toolkit root path found: /usr/lib/vmware-vcli/apps
> > 2010-03-24 17:35:12|5445|2:2|image|esx.pm:initialize(140)|vmware ESX
> > module initialized
> > 2010-03-24
> >
> 17:35:12|5445|2:2|image|State.pm:initialize(127)|VCL::Module::Provisioning::esx
> > module loaded
> > 2010-03-24 17:35:12|5445|2:2|image|Module.pm:new(132)|constructor called,
> > class=VCL::Module::Provisioning::esx
> > 2010-03-24
> > 17:35:12|5445|2:2|image|Module.pm:new(154)|VCL::Module::Provisioning::esx
> > object created
> > 2010-03-24 17:35:12|5445|2:2|image|esx.pm:initialize(138)|esx vmware
> > toolkit root path found: /usr/lib/vmware-vcli/apps
> > 2010-03-24 17:35:12|5445|2:2|image|esx.pm:initialize(140)|vmware ESX
> > module initialized
> > 2010-03-24
> >
> 17:35:12|5445|2:2|image|State.pm:initialize(131)|VCL::Module::Provisioning::esx
> > provisioner object created
> > 2010-03-24 17:35:12|5445|2:2|image|State.pm:initialize(145)|attempting to
> > load OS module: VCL::Module::OS::Linux
> > 2010-03-24
> > 17:35:12|5445|2:2|image|State.pm:initialize(151)|VCL::Module::OS::Linux
> > module loaded
> > 2010-03-24 17:35:12|5445|2:2|image|Module.pm:new(132)|constructor called,
> > class=VCL::Module::OS::Linux
> > 2010-03-24
> > 17:35:12|5445|2:2|image|Module.pm:new(154)|VCL::Module::OS::Linux object
> > created
> > 2010-03-24
> > 17:35:12|5445|2:2|image|State.pm:initialize(154)|VCL::Module::OS::Linux
> OS
> > object created
> > 2010-03-24 17:35:12|5445|2:2|image|State.pm:initialize(169)|returning 1
> > 2010-03-24 17:35:12|5445|2:2|image|vcld:make_new_child(591)|VCL::image
> > object created and initialized
> > No recipient addresses found in header
> > 2010-03-24 17:35:12|5445|2:2|image|utils.pm:mail(1348)|SUCCESS --
> Sending
> > mail To: , VCL IMAGE Creation Started: esx3-basewinxp-v0
> > 2010-03-24 17:35:12|5445|2:2|image|utils.pm:
> run_ssh_command(6180)|executing
> > SSH command on 192.168.129.37:
> > |5445|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-24 17:35:12|5445|2:2|image|utils.pm:
> run_ssh_command(6262)|run_ssh_command
> > output:
> > |5445|2:2|image| none
> > 2010-03-24 17:35:12|5445|2:2|image|utils.pm:run_ssh_command(6276)|SSH
> > command executed on 192.168.129.37, returning (0, "none")
> >
> > |5445|2:2|image| ---- WARNING ----
> > |5445|2:2|image| 2010-03-24 17:35:12|5445|2:2|image|esx.pm:
> does_image_exist(930)|image
> > /install/image/vmware_images/golden/esx3-basewinxp-v0 does NOT exists
> > |5445|2:2|image| ( 0) utils.pm, notify (line: 737)
> > |5445|2:2|image| (-1) esx.pm, does_image_exist (line: 930)
> > |5445|2:2|image| (-2) image.pm, process (line: 135)
> > |5445|2:2|image| (-3) vcld, make_new_child (line: 594)
> > |5445|2:2|image| (-4) vcld, main (line: 341)
> >
> > 2010-03-24 17:35:12|5445|2:2|image|image.pm:process(145)|image
> > esx3-basewinxp-v0 does not exist in the repository
> > 2010-03-24 17:35:12|5445|2:2|image|DataStructure.pm:_automethod(697)|data
> > structure updated:
> $self->request_data->{reservation}{2}{image}{lastupdate}
> > |5445|2:2|image| image_lastupdate = 2010-03-24 17:35:12
> > 2010-03-24 17:35:12|5445|2:2|image|DataStructure.pm:_automethod(697)|data
> > structure updated:
> > $self->request_data->{reservation}{2}{imagerevision}{datecreated}
> > |5445|2:2|image| imagerevision_date_created = 2010-03-24 17:35:12
> > 2010-03-24 17:35:12|5445|2:2|image|image.pm:process(161)|calling
> > provisioning module's capture() subroutine
> > 2010-03-24 17:35:12|5445|2:2|image|esx.pm:
> > capture(593)|**********************************************************
> > 2010-03-24 17:35:12|5445|2:2|image|esx.pm:capture(594)|Entering ESX
> > Capture routine
> > 2010-03-24 17:35:12|5445|2:2|image|utils.pm:
> run_ssh_command(6180)|executing
> > SSH command on 192.168.129.37:
> > |5445|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/esx3-basewinxp-v0
> > 2>&1' 2>&1
> > 2010-03-24 17:35:12|5445|2:2|image|utils.pm:
> run_ssh_command(6262)|run_ssh_command
> > output:
> > |5445|2:2|image| esx3-basewinxp-v0-flat.vmdk
> > |5445|2:2|image| esx3-basewinxp-v0.nvram
> > |5445|2:2|image| esx3-basewinxp-v0.vmdk
> > |5445|2:2|image| esx3-basewinxp-v0.vmsd
> > |5445|2:2|image| esx3-basewinxp-v0.vmx
> > |5445|2:2|image| esx3-basewinxp-v0.vmxf
> > |5445|2:2|image| vmware-0.log
> > |5445|2:2|image| vmware-1.log
> > |5445|2:2|image| vmware-2.log
> > |5445|2:2|image| vmware-3.log
> > |5445|2:2|image| vmware-4.log
> > |5445|2:2|image| vmware-5.log
> > |5445|2:2|image| vmware.log
> > 2010-03-24 17:35:12|5445|2:2|image|utils.pm:run_ssh_command(6276)|SSH
> > command executed on 192.168.129.37, returning (0,
> > "esx3-basewinxp-v0-flat.vmdk es...")
> > 2010-03-24 17:35:12|5445|2:2|image|esx.pm:capture(646)|found previous
> > name= esx3-basewinxp-v0
> > 2010-03-24 17:35:12|5445|2:2|image|esx.pm:capture(648)|SSHing to node to
> > configure currentimage.txt
> > 2010-03-24 17:35:12|5445|2:2|image|utils.pm:
> run_ssh_command(6180)|executing
> > SSH command on esx3-basewinxp-v0:
> > |5445|2:2|image| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
> > esx3-basewinxp-v0 'echo esx3-basewinxp-v0 > /root/currentimage.txt' 2>&1
> > 2010-03-24 17:35:17|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:35:17
> > 2010-03-24 17:35:22|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:35:22
> > 2010-03-24 17:35:22|5445|2:2|image|utils.pm:
> run_ssh_command(6262)|run_ssh_command
> > output:
> > |5445|2:2|image| bash: /root/currentimage.txt: No such file or directory
> > 2010-03-24 17:35:22|5445|2:2|image|utils.pm:run_ssh_command(6272)|SSH
> > command executed on esx3-basewinxp-v0, command:
> > |5445|2:2|image| /usr/bin/ssh -i /etc/vcl/vcl.key -l root -p 22 -x
> > esx3-basewinxp-v0 'echo esx3-basewinxp-v0 > /root/currentimage.txt' 2>&1
> > |5445|2:2|image| returning (1, "bash: /root/currentimage.txt: ...")
> > 2010-03-24 17:35:22|5445|2:2|image|esx.pm:capture(658)|Power off
> command:
> > /usr/lib/vmware-vcli/apps/vm/vmcontrol.pl --server 'esx35-hypervisor-1'
> > --vmname esx3-basewinxp-v0 --operation poweroff --username root
> --password
> > 'xxxxxxxxxxx'
> > 2010-03-24 17:35:26|5445|2:2|image|esx.pm:capture(661)|Powered off:
> > |5445|2:2|image| virtual machine 'esx3-basewinxp-v0' under host
> > esx35-hypervisor-1.odu.edu powered off
> > 2010-03-24 17:35:26|5445|2:2|image|esx.pm:capture(663)|Waiting 5 seconds
> > for power off
> > 2010-03-24 17:35:27|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:35:27
> > 2010-03-24 17:35:31|5445|2:2|image|utils.pm:
> run_ssh_command(6180)|executing
> > SSH command on 192.168.129.37:
> > |5445|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-24 17:35:31|5445|2:2|image|utils.pm:
> run_ssh_command(6262)|run_ssh_command
> > output:
> > |5445|2:2|image| none
> > 2010-03-24 17:35:31|5445|2:2|image|utils.pm:run_ssh_command(6276)|SSH
> > command executed on 192.168.129.37, returning (0, "none")
> > 2010-03-24 17:35:31|5445|2:2|image|utils.pm:
> run_ssh_command(6180)|executing
> > SSH command on 192.168.129.37:
> > |5445|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/esx3-basewinxp-v0/esx3-basewinxp-v0.vmdk
> >
> /install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0.vmdk'
> > 2>&1
> > 2010-03-24 17:35:31|5445|2:2|image|utils.pm:
> run_ssh_command(6262)|run_ssh_command
> > output:
> > |5445|2:2|image| none
> > 2010-03-24 17:35:31|5445|2:2|image|utils.pm:run_ssh_command(6276)|SSH
> > command executed on 192.168.129.37, returning (0, "none")
> > 2010-03-24 17:35:31|5445|2:2|image|esx.pm:capture(679)|COPIED VMDK
> > SUCCESSFULLY
> > 2010-03-24 17:35:31|5445|2:2|image|utils.pm:
> run_ssh_command(6180)|executing
> > SSH command on 192.168.129.37:
> > |5445|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/esx3-basewinxp-v0/esx3-basewinxp-v0.vmx
> >
> /install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0.vmx'
> > 2>&1
> > 2010-03-24 17:35:32|5445|2:2|image|utils.pm:
> run_ssh_command(6262)|run_ssh_command
> > output:
> > |5445|2:2|image| none
> > 2010-03-24 17:35:32|5445|2:2|image|utils.pm:run_ssh_command(6276)|SSH
> > command executed on 192.168.129.37, returning (0, "none")
> > 2010-03-24 17:35:32|5445|2:2|image|esx.pm:capture(688)|COPIED VMX
> > SUCCESSFULLY
> > 2010-03-24 17:35:32|5445|2:2|image|esx.pm:capture(691)|Rewriting VMDK
> and
> > VMX files with new image name
> > 2010-03-24 17:35:32|5445|2:2|image|utils.pm:
> run_ssh_command(6180)|executing
> > SSH command on 192.168.129.37:
> > |5445|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/esx3-basewinxp-v0/"
> >
> /install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0.vmx'
> > 2>&1
> > 2010-03-24 17:35:32|5445|2:2|image|utils.pm:
> run_ssh_command(6262)|run_ssh_command
> > output:
> > |5445|2:2|image| none
> > 2010-03-24 17:35:32|5445|2:2|image|utils.pm:run_ssh_command(6276)|SSH
> > command executed on 192.168.129.37, returning (0, "none")
> > 2010-03-24 17:35:32|5445|2:2|image|utils.pm:
> run_ssh_command(6180)|executing
> > SSH command on 192.168.129.37:
> > |5445|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/esx3-basewinxp-v0/"
> >
> /install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0.vmdk'
> > 2>&1
> > 2010-03-24 17:35:32|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:35:32
> > 2010-03-24 17:35:32|5445|2:2|image|utils.pm:
> run_ssh_command(6262)|run_ssh_command
> > output:
> > |5445|2:2|image| none
> > 2010-03-24 17:35:32|5445|2:2|image|utils.pm:run_ssh_command(6276)|SSH
> > command executed on 192.168.129.37, returning (0, "none")
> > 2010-03-24 17:35:32|5445|2:2|image|esx.pm:capture(705)|Preparing to ssh
> to
> > 192.168.129.37 copy vmdk-flat from
> >
> /install/image/vmware_images/inuse/esx3-basewinxp-v0/esx3-basewinxp-v0-flat.vmdk
> > to
> >
> /install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0-flat.vmdk
> > 2010-03-24 17:35:32|5445|2:2|image|esx.pm:capture(706)|SSHing to copy
> > vmdk-flat file
> > 2010-03-24 17:35:32|5445|2:2|image|utils.pm:
> run_ssh_command(6180)|executing
> > SSH command on 192.168.129.37:
> > |5445|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/esx3-basewinxp-v0/esx3-basewinxp-v0-flat.vmdk
> >
> /install/image/vmware_images/golden/esx3-basewinxp-v0/esx3-basewinxp-v0-flat.vmdk'
> > 2>&1
> > 2010-03-24 17:35:37|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:35:37
> > 2010-03-24 17:35:42|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:35:42
> > 2010-03-24 17:35:47|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:35:47
> > 2010-03-24 17:35:52|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:35:52
> > 2010-03-24 17:35:57|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:35:57
> > 2010-03-24 17:36:02|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:36:02
> > 2010-03-24 17:36:07|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:36:07
> > 2010-03-24 17:36:12|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:36:12
> > 2010-03-24 17:36:17|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:36:17
> > 2010-03-24 17:36:22|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:36:22
> > 2010-03-24 17:36:27|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:36:27
> > 2010-03-24 17:36:32|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:36:32
> > 2010-03-24 17:36:37|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:36:37
> > 2010-03-24 17:36:42|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:36:42
> > 2010-03-24 17:36:47|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:36:47
> > 2010-03-24 17:36:52|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:36:52
> > 2010-03-24 17:36:57|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:36:57
> > 2010-03-24 17:37:02|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:37:02
> > 2010-03-24 17:37:07|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:37:07
> > 2010-03-24 17:37:12|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:37:12
> > 2010-03-24 17:37:17|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:37:17
> > 2010-03-24 17:37:22|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:37:22
> > 2010-03-24 17:37:27|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:37:27
> > 2010-03-24 17:37:32|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:37:32
> > 2010-03-24 17:37:37|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:37:37
> > 2010-03-24 17:37:42|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:37:42
> > 2010-03-24 17:37:47|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:37:47
> > 2010-03-24 17:37:53|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:37:53
> > 2010-03-24 17:37:58|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:37:58
> > 2010-03-24 17:38:03|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:38:03
> > 2010-03-24 17:38:08|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:38:08
> > 2010-03-24 17:38:13|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:38:13
> > 2010-03-24 17:38:18|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:38:18
> > 2010-03-24 17:38:20|5445|2:2|image|utils.pm:
> run_ssh_command(6262)|run_ssh_command
> > output:
> > |5445|2:2|image| none
> > 2010-03-24 17:38:20|5445|2:2|image|utils.pm:run_ssh_command(6276)|SSH
> > command executed on 192.168.129.37, returning (0, "none")
> > 2010-03-24 17:38:20|5445|2:2|image|image.pm:
> process(162)|esx3-basewinxp-v0
> > image was successfully captured by the provisioning module
> > 2010-03-24 17:38:20|5445|2:2|image|image.pm:
> process(219)|esx3-basewinxp-v0
> > image files successfully saved
> > 2010-03-24 17:38:20|5445|2:2|image|utils.pm:
> update_request_state(2186)|request
> > 2 state updated to: completed, laststate to: image
> > 2010-03-24 17:38:20|5445|2:2|image|image.pm:process(222)|request state
> > updated to completed, laststate to image
> > 2010-03-24 17:38:20|5445|2:2|image|esx.pm:get_image_size(960)|getting
> size
> > of image: esx3-basewinxp-v0
> > 2010-03-24 17:38:20|5445|2:2|image|utils.pm:
> run_ssh_command(6180)|executing
> > SSH command on 192.168.129.37:
> > |5445|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-24 17:38:21|5445|2:2|image|utils.pm:
> run_ssh_command(6262)|run_ssh_command
> > output:
> > |5445|2:2|image| total 4198412
> > |5445|2:2|image| 4198404 esx3-basewinxp-v0-flat.vmdk
> > |5445|2:2|image| 4 esx3-basewinxp-v0.vmdk
> > |5445|2:2|image| 4 esx3-basewinxp-v0.vmx
> > 2010-03-24 17:38:21|5445|2:2|image|utils.pm:run_ssh_command(6276)|SSH
> > command executed on 192.168.129.37, returning (0, "total 4198412 4198404
> > esx3-bas...")
> > 2010-03-24 17:38:21|5445|2:2|image|image.pm:process(231)|size of
> > esx3-basewinxp-v0: 4100
> > 2010-03-24 17:38:21|5445|2:2|image|DataStructure.pm:_automethod(697)|data
> > structure updated: $self->request_data->{reservation}{2}{image}{size}
> > |5445|2:2|image| image_size = 4100
> > 2010-03-24 17:38:21|5445|2:2|image|image.pm:process(260)|image and
> > imagerevision tables updated for image=10, imagerevision=11,
> > name=esx3-basewinxp-v0, lastupdate=2010-03-24 17:35:12, deleted=0,
> size=4100
> > 2010-03-24 17:38:22|5445|2:2|image|utils.pm:mail(1348)|SUCCESS --
> Sending
> > mail To: root@localhost, VCL -- No Apps (ESXi WinXP) Image Creation
> > Succeeded
> > No recipient addresses found in header
> > 2010-03-24 17:38:22|5445|2:2|image|utils.pm:mail(1348)|SUCCESS --
> Sending
> > mail To: , VCL IMAGE Creation Completed: esx3-basewinxp-v0
> > 2010-03-24 17:38:22|5445|2:2|image|utils.pm:insertloadlog(4710)|inserted
> > computer=3, loadimagevmware, VCL::utils::insert_reload_request: switching
> > request state to reload
> > 2010-03-24 17:38:22|5445|2:2|image|utils.pm:
> update_computer_state(2228)|computer
> > 3 state updated to: reload
> > 2010-03-24 17:38:22|5445|2:2|image|utils.pm:
> insert_reload_request(9117)|req=2:
> > setting computerid 3 into reload state
> > 2010-03-24 17:38:22|5445|2:2|image|utils.pm:
> insert_request(9020)|inserted
> > new reload request into request table, request id=3
> > 2010-03-24 17:38:22|5445|2:2|image|utils.pm:
> insert_request(9051)|inserted
> > new reload request into reservation table, reservation id=3
> > 2010-03-24 17:38:22|5445|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-24 17:38:22|5445|2:2|image|utils.pm:insertloadlog(4710)|inserted
> > computer=3, info, VCL::utils::insert_reload_request: created new reload
> > request
> > 2010-03-24 17:38:22|5445|2:2|image|image.pm:
> reservation_successful(348)|inserted
> > reload request into database for computer id=3
> > 2010-03-24 17:38:22|5445|2:2|image|utils.pm:switch_state(8018)|called
> from
> > VCL::image::reservation_successful(351)
> > 2010-03-24 17:38:22|5445|2:2|image|utils.pm:switch_state(8054)|parent:
> > parent reservation ID for this request: 2
> > 2010-03-24 17:38:22|5445|2:2|image|utils.pm:insertloadlog(4710)|inserted
> > computer=3, info, VCL::image: switching request state to complete
> > 2010-03-24 17:38:22|5445|2:2|image|utils.pm:
> update_request_state(2186)|request
> > 2 state updated to: complete, laststate to: image
> > 2010-03-24 17:38:22|5445|2:2|image|utils.pm:switch_state(8078)|req=2:
> > request state changed: image->complete, laststate: image->image
> > 2010-03-24 17:38:22|5445|2:2|image|utils.pm:insertloadlog(4710)|inserted
> > computer=3, info, VCL::image: request state changed to complete,
> laststate
> > to image
> > 2010-03-24 17:38:22|5445|2:2|image|utils.pm:switch_state(8088)|req=2:
> > computer state not specified, esx3-basewinxp-v0 state not changed
> > 2010-03-24 17:38:22|5445|2:2|image|utils.pm:switch_state(8106)|req=2:
> log
> > table id=0, ending set to EOR
> > 2010-03-24 17:38:22|5445|2:2|image|utils.pm:insertloadlog(4710)|inserted
> > computer=3, info, VCL::image: process exiting
> > 2010-03-24 17:38:22|5445|2:2|image|utils.pm:switch_state(8122)|req=2:
> > process exiting
> > 2010-03-24 17:38:22|5445|2:2|image|State.pm:DESTROY(905)|destructor
> called,
> > ref($self)=VCL::image
> > 2010-03-24 17:38:22|5445|2:2|image|utils.pm:
> delete_computerloadlog_reservation(7551)|removing
> > computerloadlog entries matching loadstate = begin
> > 2010-03-24 17:38:22|5445|2:2|image|utils.pm:
> delete_computerloadlog_reservation(7598)|deleted
> > rows from computerloadlog for reservation id=2
> > 2010-03-24 17:38:22|5445|2:2|image|State.pm:DESTROY(912)|removed
> > computerloadlog rows with loadstate=begin for reservation
> > 2010-03-24 17:38:22|5445|2:2|image|State.pm:DESTROY(924)|number of
> database
> > handles state process created: 1
> > 2010-03-24 17:38:22|5445|2:2|image|State.pm:DESTROY(933)|process has a
> > database handle stored in $ENV{dbh}, attempting disconnect
> > 2010-03-24 17:38:22|5445|2:2|image|State.pm:DESTROY(935)|$ENV{dbh}:
> > database disconnect successful
> > 2010-03-24 17:38:22|5445|2:2|image|State.pm:DESTROY(949)|VCL::image
> process
> > 5445 exiting
> > 2010-03-24 17:38:22|5443|vcld:REAPER(744)|VCL process exited for
> > reservation 2
> > 2010-03-24 17:38:22|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:38:22
> > 2010-03-24 17:38:22|5443|3:3|reload|utils.pm:
> reservation_being_processed(9634)|computerloadlog
> > 'begin' entry does NOT exist for reservation 3
> > 2010-03-24 17:38:22|5443|3:3|reload|utils.pm:
> reservation_being_processed(9686)|reservation
> > is NOT currently being processed
> > 2010-03-24 17:38:22|5443|3:3|reload|vcld:main(276)|reservation 3 is NOT
> > already being processed
> >
> > |5443|3:3|reload| ---- WARNING ----
> > |5443|3:3|reload| 2010-03-24 17:38:22|5443|3:3|reload|utils.pm:
> get_request_info(5218)|preferredimageid
> > is not set for computer id=3
> > |5443|3:3|reload| ( 0) utils.pm, notify (line: 737)
> > |5443|3:3|reload| (-1) utils.pm, get_request_info (line: 5218)
> > |5443|3:3|reload| (-2) vcld, main (line: 280)
> >
> > 2010-03-24 17:38:22|5443|3:3|reload|utils.pm:
> get_request_info(5354)|standalone
> > affiliation found: Local
> > 2010-03-24 17:38:22|5443|3:3|reload|utils.pm:
> get_management_node_info(6815)|management
> > node info retrieved from database for colbert
> > 2010-03-24 17:38:22|5443|3:3|reload|vcld:main(281)|retrieved request
> > information from database
> > 2010-03-24
> >
> 17:38:22|5443|3:3|reload|DataStructure.pm:is_parent_reservation(854)|returning
> > true: parent reservation ID for this request: 3
> > 2010-03-24 17:38:22|5443|3:3|reload|utils.pm:
> update_request_state(2186)|request
> > 3 state updated to: pending, laststate to: reload
> > 2010-03-24 17:38:22|5443|3:3|reload|utils.pm:
> insertloadlog(4710)|inserted
> > computer=3, begin, beginning to process, state is reload
> > 2010-03-24 17:38:22|5443|3:3|reload|vcld:make_new_child(501)|request will
> > be processed by new.pm
> > 2010-03-24 17:38:22|5443|3:3|reload|vcld:make_new_child(509)|loaded
> > VCL::new module
> > 2010-03-24 17:38:22|5665|3:3|reload|vcld:make_new_child(582)|vcld
> > environment variable set to 0 for this process
> > 2010-03-24 17:38:22|5665|3:3|reload|Module.pm:new(132)|constructor
> called,
> > class=VCL::new
> > 2010-03-24 17:38:22|5665|3:3|reload|Module.pm:new(154)|VCL::new object
> > created
> > 2010-03-24 17:38:22|5443|3:3|reload|vcld:make_new_child(566)|current
> number
> > of forked kids: 1
> > 2010-03-24 17:38:22|5665|3:3|reload|State.pm:initialize(85)|obtained a
> > database handle for this state process, stored as $ENV{dbh}
> > 2010-03-24 17:38:22|5665|3:3|reload|State.pm:check_image_os(820)|no
> > corrections need to be made, not an imaging request, returning 1
> > 2010-03-24
> >
> 17:38:22|5665|3:3|reload|DataStructure.pm:is_parent_reservation(854)|returning
> > true: parent reservation ID for this request: 3
> > 2010-03-24 17:38:22|5665|3:3|reload|utils.pm:
> rename_vcld_process(7863)|reservation
> > count: 1
> > 2010-03-24 17:38:22|5665|3:3|reload|utils.pm:
> rename_vcld_process(7882)|PARENTIMAGE:
> > 1
> > 2010-03-24 17:38:22|5665|3:3|reload|utils.pm:
> rename_vcld_process(7883)|SUBIMAGE:
> > 0
> > 2010-03-24 17:38:22|5665|3:3|reload|utils.pm:
> rename_vcld_process(7901)|renamed
> > process to 'vcld VCL::new 3:3 reload'
> > 2010-03-24
> >
> 17:38:22|5665|3:3|reload|DataStructure.pm:is_parent_reservation(854)|returning
> > true: parent reservation ID for this request: 3
> > 2010-03-24
> >
> 17:38:22|5665|3:3|reload|DataStructure.pm:is_parent_reservation(854)|returning
> > true: parent reservation ID for this request: 3
> > 2010-03-24 17:38:22|5665|3:3|reload|State.pm:initialize(121)|attempting
> to
> > load provisioning module: VCL::Module::Provisioning::esx
> > 2010-03-24 17:38:22|5443|2:2|complete|vcld:main(250)|request deleted
> > 2010-03-24 17:38:22|5665|3:3|reload|esx.pm:initialize(138)|esx vmware
> > toolkit root path found: /usr/lib/vmware-vcli/apps
> > 2010-03-24 17:38:22|5665|3:3|reload|esx.pm:initialize(140)|vmware ESX
> > module initialized
> > 2010-03-24
> >
> 17:38:22|5665|3:3|reload|State.pm:initialize(127)|VCL::Module::Provisioning::esx
> > module loaded
> > 2010-03-24 17:38:22|5665|3:3|reload|Module.pm:new(132)|constructor
> called,
> > class=VCL::Module::Provisioning::esx
> > 2010-03-24
> >
> 17:38:22|5665|3:3|reload|Module.pm:new(154)|VCL::Module::Provisioning::esx
> > object created
> > 2010-03-24 17:38:22|5665|3:3|reload|esx.pm:initialize(138)|esx vmware
> > toolkit root path found: /usr/lib/vmware-vcli/apps
> > 2010-03-24 17:38:22|5665|3:3|reload|esx.pm:initialize(140)|vmware ESX
> > module initialized
> > 2010-03-24
> >
> 17:38:22|5665|3:3|reload|State.pm:initialize(131)|VCL::Module::Provisioning::esx
> > provisioner object created
> > 2010-03-24 17:38:22|5665|3:3|reload|State.pm:initialize(145)|attempting
> to
> > load OS module: VCL::Module::OS::Linux
> > 2010-03-24
> > 17:38:22|5665|3:3|reload|State.pm:initialize(151)|VCL::Module::OS::Linux
> > module loaded
> > 2010-03-24 17:38:22|5665|3:3|reload|Module.pm:new(132)|constructor
> called,
> > class=VCL::Module::OS::Linux
> > 2010-03-24
> > 17:38:22|5665|3:3|reload|Module.pm:new(154)|VCL::Module::OS::Linux object
> > created
> > 2010-03-24
> > 17:38:22|5665|3:3|reload|State.pm:initialize(154)|VCL::Module::OS::Linux
> OS
> > object created
> > 2010-03-24 17:38:22|5665|3:3|reload|State.pm:initialize(169)|returning 1
> > 2010-03-24 17:38:22|5665|3:3|reload|vcld:make_new_child(591)|VCL::new
> > object created and initialized
> > 2010-03-24
> >
> 17:38:22|5665|3:3|reload|DataStructure.pm:is_parent_reservation(854)|returning
> > true: parent reservation ID for this request: 3
> > 2010-03-24
> >
> 17:38:22|5665|3:3|reload|DataStructure.pm:get_computer_state_name(1946)|attempting
> > to retrieve current state of computer esx3-basewinxp-v0 from the database
> > 2010-03-24
> >
> 17:38:22|5665|3:3|reload|DataStructure.pm:get_computer_state_name(1977)|retrieved
> > current state of computer esx3-basewinxp-v0 from the database: reload
> > 2010-03-24
> 17:38:22|5665|3:3|reload|DataStructure.pm:_automethod(697)|data
> > structure updated:
> > $self->request_data->{reservation}{3}{computer}{state}{name}
> > |5665|3:3|reload| computer_state_name = reload
> >
> > |5665|3:3|reload| ---- WARNING ----
> > |5665|3:3|reload| 2010-03-24
> > 17:38:22|5665|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}
> > |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> > |5665|3:3|reload| (-1) DataStructure.pm, _automethod (line: 675)
> > |5665|3:3|reload| (-2) Autoload.pm, __ANON__ (line: 80)
> > |5665|3:3|reload| (-3) new.pm, process (line: 106)
> > |5665|3:3|reload| (-4) vcld, make_new_child (line: 594)
> > |5665|3:3|reload| (-5) vcld, main (line: 341)
> >
> >
> > |5665|3:3|reload| ---- WARNING ----
> > |5665|3:3|reload| 2010-03-24
> > 17:38:22|5665|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}
> > |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> > |5665|3:3|reload| (-1) DataStructure.pm, _automethod (line: 675)
> > |5665|3:3|reload| (-2) Autoload.pm, __ANON__ (line: 80)
> > |5665|3:3|reload| (-3) new.pm, process (line: 107)
> > |5665|3:3|reload| (-4) vcld, make_new_child (line: 594)
> > |5665|3:3|reload| (-5) vcld, main (line: 341)
> >
> > 2010-03-24 17:38:22|5665|3:3|reload|utils.pm:
> get_management_node_id(9364)|environment
> > variable: 1
> > 2010-03-24 17:38:22|5665|3:3|reload|new.pm:process(134)|reservation is
> > parent = 1
> > 2010-03-24 17:38:22|5665|3:3|reload|new.pm:process(135)|preload only = 0
> > 2010-03-24 17:38:22|5665|3:3|reload|new.pm:process(136)|originating
> > request state = reload
> > 2010-03-24 17:38:22|5665|3:3|reload|new.pm:process(137)|originating
> > request laststate = image
> > 2010-03-24 17:38:22|5665|3:3|reload|new.pm:process(138)|originating
> > computer state = reload
> > 2010-03-24 17:38:22|5665|3:3|reload|new.pm:process(139)|originating
> > computer type = virtualmachine
> > 2010-03-24
> >
> 17:38:22|5665|3:3|reload|DataStructure.pm:is_parent_reservation(854)|returning
> > true: parent reservation ID for this request: 3
> > 2010-03-24
> >
> 17:38:22|5665|3:3|reload|DataStructure.pm:get_computer_state_name(1946)|attempting
> > to retrieve current state of computer esx3-basewinxp-v0 from the database
> > 2010-03-24
> >
> 17:38:22|5665|3:3|reload|DataStructure.pm:get_computer_state_name(1977)|retrieved
> > current state of computer esx3-basewinxp-v0 from the database: reload
> > 2010-03-24
> 17:38:22|5665|3:3|reload|DataStructure.pm:_automethod(697)|data
> > structure updated:
> > $self->request_data->{reservation}{3}{computer}{state}{name}
> > |5665|3:3|reload| computer_state_name = reload
> >
> > |5665|3:3|reload| ---- WARNING ----
> > |5665|3:3|reload| 2010-03-24
> > 17:38:22|5665|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}
> > |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> > |5665|3:3|reload| (-1) DataStructure.pm, _automethod (line: 675)
> > |5665|3:3|reload| (-2) Autoload.pm, __ANON__ (line: 80)
> > |5665|3:3|reload| (-3) new.pm, computer_not_being_used (line: 750)
> > |5665|3:3|reload| (-4) new.pm, process (line: 170)
> > |5665|3:3|reload| (-5) vcld, make_new_child (line: 594)
> > |5665|3:3|reload| (-6) vcld, main (line: 341)
> >
> >
> > |5665|3:3|reload| ---- WARNING ----
> > |5665|3:3|reload| 2010-03-24
> > 17:38:22|5665|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}
> > |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> > |5665|3:3|reload| (-1) DataStructure.pm, _automethod (line: 675)
> > |5665|3:3|reload| (-2) Autoload.pm, __ANON__ (line: 80)
> > |5665|3:3|reload| (-3) new.pm, computer_not_being_used (line: 751)
> > |5665|3:3|reload| (-4) new.pm, process (line: 170)
> > |5665|3:3|reload| (-5) vcld, make_new_child (line: 594)
> > |5665|3:3|reload| (-6) vcld, main (line: 341)
> >
> > 2010-03-24 17:38:22|5665|3:3|reload|utils.pm:
> get_management_node_id(9364)|environment
> > variable: 1
> > 2010-03-24 17:38:22|5665|3:3|reload|new.pm:
> computer_not_being_used(788)|esx3-basewinxp-v0
> > state is reload
> > 2010-03-24 17:38:22|5665|3:3|reload|new.pm:
> computer_not_being_used(798)|esx3-basewinxp-v0
> > is available, its state is reload
> > 2010-03-24 17:38:22|5665|3:3|reload|new.pm:
> process(170)|esx3-basewinxp-v0
> > is not being used
> > 2010-03-24
> >
> 17:38:22|5665|3:3|reload|DataStructure.pm:is_parent_reservation(854)|returning
> > true: parent reservation ID for this request: 3
> > 2010-03-24
> >
> 17:38:22|5665|3:3|reload|DataStructure.pm:get_computer_state_name(1946)|attempting
> > to retrieve current state of computer esx3-basewinxp-v0 from the database
> > 2010-03-24
> >
> 17:38:22|5665|3:3|reload|DataStructure.pm:get_computer_state_name(1977)|retrieved
> > current state of computer esx3-basewinxp-v0 from the database: reload
> > 2010-03-24
> 17:38:22|5665|3:3|reload|DataStructure.pm:_automethod(697)|data
> > structure updated:
> > $self->request_data->{reservation}{3}{computer}{state}{name}
> > |5665|3:3|reload| computer_state_name = reload
> >
> > |5665|3:3|reload| ---- WARNING ----
> > |5665|3:3|reload| 2010-03-24
> > 17:38:22|5665|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}
> > |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> > |5665|3:3|reload| (-1) DataStructure.pm, _automethod (line: 675)
> > |5665|3:3|reload| (-2) Autoload.pm, __ANON__ (line: 80)
> > |5665|3:3|reload| (-3) new.pm, reload_image (line: 480)
> > |5665|3:3|reload| (-4) new.pm, process (line: 266)
> > |5665|3:3|reload| (-5) vcld, make_new_child (line: 594)
> > |5665|3:3|reload| (-6) vcld, main (line: 341)
> >
> >
> > |5665|3:3|reload| ---- WARNING ----
> > |5665|3:3|reload| 2010-03-24
> > 17:38:22|5665|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}
> > |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> > |5665|3:3|reload| (-1) DataStructure.pm, _automethod (line: 675)
> > |5665|3:3|reload| (-2) Autoload.pm, __ANON__ (line: 80)
> > |5665|3:3|reload| (-3) new.pm, reload_image (line: 481)
> > |5665|3:3|reload| (-4) new.pm, process (line: 266)
> > |5665|3:3|reload| (-5) vcld, make_new_child (line: 594)
> > |5665|3:3|reload| (-6) vcld, main (line: 341)
> >
> > 2010-03-24 17:38:22|5665|3:3|reload|utils.pm:
> get_management_node_id(9364)|environment
> > variable: 1
> > 2010-03-24 17:38:22|5665|3:3|reload|new.pm:reload_image(514)|calling
> > VCL::Module::Provisioning::esx->node_status()
> > 2010-03-24 17:38:22|5665|3:3|reload|utils.pm:
> insertloadlog(4710)|inserted
> > computer=3, statuscheck, checking status of node
> > 2010-03-24 17:38:22|5665|3:3|reload|esx.pm:node_status(787)|Entering
> > node_status, checking status of esx3-basewinxp-v0
> > 2010-03-24 17:38:22|5665|3:3|reload|esx.pm:
> node_status(788)|request_for_imaging:
> > 0
> > 2010-03-24 17:38:22|5665|3:3|reload|esx.pm:node_status(789)|requeseted
> > image name: esx3-basewinxp-v0
> > 2010-03-24 17:38:22|5665|3:3|reload|esx.pm:node_status(819)|checking if
> > esx3-basewinxp-v0 is pingable
> > 2010-03-24 17:38:23|5665|3:3|reload|esx.pm:
> node_status(825)|esx3-basewinxp-v0
> > is not pingable (0)
> > 2010-03-24 17:38:23|5665|3:3|reload|new.pm:reload_image(560)|node_status
> > returned a scalar: RELOAD
> > 2010-03-24 17:38:23|5665|3:3|reload|new.pm:reload_image(576)|request
> state
> > is reload, node will be reloaded regardless of status
> > 2010-03-24 17:38:23|5665|3:3|reload|new.pm:reload_image(602)|node status
> > is reload, esx3-basewinxp-v0 will be reloaded
> > 2010-03-24 17:38:23|5665|3:3|reload|utils.pm:
> insertloadlog(4710)|inserted
> > computer=3, loadimageblade, esx3-basewinxp-v0 must be reloaded with
> > esx3-basewinxp-v0
> > 2010-03-24 17:38:23|5665|3:3|reload|new.pm:reload_image(616)|calling
> > VCL::Module::Provisioning::esx->does_image_exist()
> > 2010-03-24 17:38:23|5665|3:3|reload|utils.pm:
> run_ssh_command(6180)|executing
> > SSH command on 192.168.129.37:
> > |5665|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-24 17:38:23|5665|3:3|reload|utils.pm:
> run_ssh_command(6262)|run_ssh_command
> > output:
> > |5665|3:3|reload| esx3-basewinxp-v0
> > 2010-03-24 17:38:23|5665|3:3|reload|utils.pm:run_ssh_command(6276)|SSH
> > command executed on 192.168.129.37, returning (0, "esx3-basewinxp-v0")
> > 2010-03-24 17:38:23|5665|3:3|reload|esx.pm:does_image_exist(917)|image
> > esx3-basewinxp-v0 exists
> > 2010-03-24 17:38:23|5665|3:3|reload|new.pm:
> reload_image(619)|esx3-basewinxp-v0
> > exists on this management node
> > 2010-03-24 17:38:23|5665|3:3|reload|utils.pm:
> insertloadlog(4710)|inserted
> > computer=3, doesimageexists, confirmed image exists
> > 2010-03-24 17:38:23|5665|3:3|reload|utils.pm:
> update_computer_state(2228)|computer
> > 3 state updated to: reloading
> > 2010-03-24 17:38:23|5665|3:3|reload|new.pm:reload_image(652)|computer
> > esx3-basewinxp-v0 state set to reloading
> > 2010-03-24 17:38:23|5665|3:3|reload|utils.pm:
> insertloadlog(4710)|inserted
> > computer=3, info, computer state updated to reloading
> > 2010-03-24 17:38:23|5665|3:3|reload|new.pm:reload_image(663)|calling
> > VCL::Module::Provisioning::esx->load() subroutine
> > 2010-03-24 17:38:23|5665|3:3|reload|utils.pm:
> insertloadlog(4710)|inserted
> > computer=3, info, calling VCL::Module::Provisioning::esx->load()
> subroutine
> > 2010-03-24 17:38:23|5665|3:3|reload|esx.pm:
> > load(165)|****************************************************
> >
> > |5665|3:3|reload| ---- WARNING ----
> > |5665|3:3|reload| 2010-03-24
> > 17:38:23|5665|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}
> > |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> > |5665|3:3|reload| (-1) DataStructure.pm, _automethod (line: 675)
> > |5665|3:3|reload| (-2) Autoload.pm, __ANON__ (line: 80)
> > |5665|3:3|reload| (-3) esx.pm, load (line: 181)
> > |5665|3:3|reload| (-4) new.pm, reload_image (line: 665)
> > |5665|3:3|reload| (-5) new.pm, process (line: 266)
> > |5665|3:3|reload| (-6) vcld, make_new_child (line: 594)
> >
> >
> > |5665|3:3|reload| ---- WARNING ----
> > |5665|3:3|reload| 2010-03-24
> > 17:38:23|5665|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}
> > |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> > |5665|3:3|reload| (-1) DataStructure.pm, _automethod (line: 675)
> > |5665|3:3|reload| (-2) Autoload.pm, __ANON__ (line: 80)
> > |5665|3:3|reload| (-3) esx.pm, load (line: 182)
> > |5665|3:3|reload| (-4) new.pm, reload_image (line: 665)
> > |5665|3:3|reload| (-5) new.pm, process (line: 266)
> > |5665|3:3|reload| (-6) vcld, make_new_child (line: 594)
> >
> > 2010-03-24 17:38:23|5665|3:3|reload|esx.pm:load(193)|Calling
> > get_vmware_host_info
> > No recipient addresses found in header
> > 2010-03-24 17:38:26|5665|3:3|reload|utils.pm:mail(1348)|SUCCESS --
> Sending
> > mail To: , PROBLEM -- esx.pm
> >
> > |5665|3:3|reload| ---- CRITICAL ----
> > |5665|3:3|reload| 2010-03-24 17:38:23|5665|3:3|reload|esx.pm:
> get_vmware_host_info(1012)|AMIT
> > DEBUGGING: esx35-hypervisor-1.odu.edu
> > |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> > |5665|3:3|reload| (-1) esx.pm, get_vmware_host_info (line: 1012)
> > |5665|3:3|reload| (-2) esx.pm, load (line: 194)
> > |5665|3:3|reload| (-3) new.pm, reload_image (line: 665)
> > |5665|3:3|reload| (-4) new.pm, process (line: 266)
> > |5665|3:3|reload| (-5) vcld, make_new_child (line: 594)
> > |5665|3:3|reload| (-6) vcld, main (line: 341)
> >
> > 2010-03-24 17:38:27|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:38:27
> > 2010-03-24 17:38:29|5665|3:3|reload|esx.pm:
> get_vmware_host_info(1019)|host
> > info output for esx35-hypervisor-1
> > |5665|3:3|reload| Host Information
> > |5665|3:3|reload| Host Name: esx35-hypervisor-1.odu.edu
> > 2010-03-24 17:38:29|5665|3:3|reload|esx.pm:
> get_vmware_host_info(1025)|found
> > hostname_value= esx35-hypervisor-1.odu.edu
> > 2010-03-24 17:38:29|5665|3:3|reload|esx.pm:load(197)|Collected
> > esx35-hypervisor-1.odu.edu for vmware host name
> > 2010-03-24 17:38:29|5665|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-24 17:38:29|5665|3:3|reload|esx.pm:load(211)|Entered ESX module,
> > loading esx3-basewinxp-v0 on esx3-basewinxp-v0 (on
> > esx35-hypervisor-1.odu.edu) for reservation 3
> > 2010-03-24 17:38:29|5665|3:3|reload|esx.pm:load(212)|Datastore:
> > 192.168.129.37:/install/image/vmware_images
> > 2010-03-24 17:38:29|5665|3:3|reload|esx.pm:load(223)|VM info command:
> > /usr/lib/vmware-vcli/apps/vm/vminfo.pl --server 'esx35-hypervisor-1'
> > --vmname esx3-basewinxp-v0 --username root --password 'xxxxxxxxxxx'
> > 2010-03-24 17:38:30|5665|3:3|reload|esx.pm:load(226)|VM info output:
> > |5665|3:3|reload| Information of Virtual Machine esx3-basewinxp-v0
> > |5665|3:3|reload| Name: esx3-basewinxp-v0
> > |5665|3:3|reload| No. of CPU(s): 2
> > |5665|3:3|reload| Memory Size: 512
> > |5665|3:3|reload| Virtual Disks: 1
> > |5665|3:3|reload| Template: 0
> > |5665|3:3|reload| vmPathName: [localstore]
> > esx3-basewinxp-v0/esx3-basewinxp-v0.vmx
> > |5665|3:3|reload| Guest OS: Not Known
> > |5665|3:3|reload| guestId: Not Known
> > |5665|3:3|reload| Host name: Not Known
> > |5665|3:3|reload| IP Address: Not Known
> > |5665|3:3|reload| VMware Tools: VMware Tools is not running.
> > |5665|3:3|reload| Cpu usage: Not Known
> > |5665|3:3|reload| Host memory usage: Not Known
> > |5665|3:3|reload| Guest memory usage: Not Known
> > |5665|3:3|reload| Overall Status: The entity is OK
> > 2010-03-24 17:38:30|5665|3:3|reload|esx.pm:load(237)|Power off command:
> > /usr/lib/vmware-vcli/apps/vm/vmcontrol.pl --server 'esx35-hypervisor-1'
> > --vmname esx3-basewinxp-v0 --operation poweroff --username root
> --password
> > 'xxxxxxxxxxx'
> > 2010-03-24 17:38:32|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:38:32
> > 2010-03-24 17:38:32|5665|3:3|reload|esx.pm:load(240)|Powered off:
> > |5665|3:3|reload| Error in 'esx3-basewinxp-v0' under host
> > esx35-hypervisor-1.odu.edu: The attempted operation cannot be performed
> in
> > the current state
> > 2010-03-24 17:38:32|5665|3:3|reload|esx.pm:load(253)|Un-Register
> Command:
> > /usr/lib/vmware-vcli/apps/vm/vmregister.pl --server 'esx35-hypervisor-1'
> > --username root --password 'xxxxxxxxxxx' --vmxpath
> > '[VCL]/inuse/esx3-basewinxp-v0/esx3-basewinxp-v0.vmx' --operation
> unregister
> > --vmname esx3-basewinxp-v0 --pool Resources --hostname '
> > esx35-hypervisor-1.odu.edu' --datacenter 'ha-datacenter'
> > 2010-03-24 17:38:35|5665|3:3|reload|esx.pm:load(256)|Un-Registered:
> > |5665|3:3|reload| Unregister of VM 'esx3-basewinxp-v0' successfully
> > completed under host esx35-hypervisor-1.odu.edu
> > 2010-03-24 17:38:35|5665|3:3|reload|utils.pm:
> run_ssh_command(6180)|executing
> > SSH command on 192.168.129.37:
> > |5665|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/esx3-basewinxp-v0'
> > 2>&1
> > 2010-03-24 17:38:36|5665|3:3|reload|utils.pm:
> run_ssh_command(6262)|run_ssh_command
> > output:
> > |5665|3:3|reload| none
> > 2010-03-24 17:38:36|5665|3:3|reload|utils.pm:run_ssh_command(6276)|SSH
> > command executed on 192.168.129.37, returning (0, "none")
> > 2010-03-24 17:38:36|5665|3:3|reload|esx.pm:load(262)|Removed old vm
> folder
> > 2010-03-24 17:38:36|5665|3:3|reload|utils.pm:
> run_ssh_command(6180)|executing
> > SSH command on 192.168.129.37:
> > |5665|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/esx3-basewinxp-v0'
> > 2>&1
> > 2010-03-24 17:38:36|5665|3:3|reload|utils.pm:
> run_ssh_command(6262)|run_ssh_command
> > output:
> > |5665|3:3|reload| none
> > 2010-03-24 17:38:36|5665|3:3|reload|utils.pm:run_ssh_command(6276)|SSH
> > command executed on 192.168.129.37, returning (0, "none")
> > 2010-03-24 17:38:36|5665|3:3|reload|utils.pm:
> run_ssh_command(6180)|executing
> > SSH command on 192.168.129.37:
> > |5665|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/esx3-basewinxp-v0/esx3-basewinxp-v0.vmdk'
> > 2>&1
> > 2010-03-24 17:38:36|5665|3:3|reload|utils.pm:
> run_ssh_command(6262)|run_ssh_command
> > output:
> > |5665|3:3|reload| none
> > 2010-03-24 17:38:36|5665|3:3|reload|utils.pm:run_ssh_command(6276)|SSH
> > command executed on 192.168.129.37, returning (0, "none")
> > 2010-03-24 17:38:36|5665|3:3|reload|esx.pm:load(278)|COPIED VMDK
> > SUCCESSFULLY
> > 2010-03-24 17:38:36|5665|3:3|reload|utils.pm:
> run_ssh_command(6180)|executing
> > SSH command on 192.168.129.37:
> > |5665|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/esx3-basewinxp-v0/esx3-basewinxp-v0-flat.vmdk'
> > 2>&1
> > 2010-03-24 17:38:37|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:38:37
> > 2010-03-24 17:38:42|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:38:42
> > 2010-03-24 17:38:47|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:38:47
> > 2010-03-24 17:38:52|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:38:52
> > 2010-03-24 17:38:57|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:38:57
> > 2010-03-24 17:39:02|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:39:02
> > 2010-03-24 17:39:07|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:39:07
> > 2010-03-24 17:39:12|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:39:12
> > 2010-03-24 17:39:18|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:39:17
> > 2010-03-24 17:39:23|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:39:23
> > 2010-03-24 17:39:28|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:39:28
> > 2010-03-24 17:39:28|5665|3:3|reload|utils.pm:
> run_ssh_command(6262)|run_ssh_command
> > output:
> > |5665|3:3|reload| none
> > 2010-03-24 17:39:28|5665|3:3|reload|utils.pm:run_ssh_command(6276)|SSH
> > command executed on 192.168.129.37, returning (0, "none")
> > 2010-03-24 17:39:28|5665|3:3|reload|utils.pm:
> run_ssh_command(6180)|executing
> > SSH command on 192.168.129.37:
> > |5665|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/esx3-basewinxp-v0/esx3-basewinxp-v0.vmdk
> > 2>&1' 2>&1
> > 2010-03-24 17:39:29|5665|3:3|reload|utils.pm:
> run_ssh_command(6262)|run_ssh_command
> > output:
> > |5665|3:3|reload| ddb.adapterType = "buslogic"
> > 2010-03-24 17:39:29|5665|3:3|reload|utils.pm:run_ssh_command(6276)|SSH
> > command executed on 192.168.129.37, returning (0, "ddb.adapterType =
> > "buslogic"")
> > 2010-03-24 17:39:29|5665|3:3|reload|esx.pm:load(311)|adapter= buslogic
> > 2010-03-24 17:39:29|5665|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.
> >
> >
> > |5665|3:3|reload| ---- WARNING ----
> > |5665|3:3|reload| 2010-03-24
> > 17:39:29|5665|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.
> > |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> > |5665|3:3|reload| (-1) vcld, warning_handler (line: 636)
> > |5665|3:3|reload| (-2) esx.pm, load (line: 343)
> > |5665|3:3|reload| (-3) new.pm, reload_image (line: 665)
> > |5665|3:3|reload| (-4) new.pm, process (line: 266)
> > |5665|3:3|reload| (-5) vcld, make_new_child (line: 594)
> > |5665|3:3|reload| (-6) vcld, main (line: 341)
> >
> >
> > |5665|3:3|reload| ---- WARNING ----
> > |5665|3:3|reload| 2010-03-24
> > 17:39:29|5665|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.
> > |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> > |5665|3:3|reload| (-1) vcld, warning_handler (line: 636)
> > |5665|3:3|reload| (-2) esx.pm, load (line: 353)
> > |5665|3:3|reload| (-3) new.pm, reload_image (line: 665)
> > |5665|3:3|reload| (-4) new.pm, process (line: 266)
> > |5665|3:3|reload| (-5) vcld, make_new_child (line: 594)
> > |5665|3:3|reload| (-6) vcld, main (line: 341)
> >
> > 2010-03-24 17:39:29|5665|3:3|reload|esx.pm:load(353)|eth1 MAC address
> set
> > for vcl assigned
> >
> > |5665|3:3|reload| ---- WARNING ----
> > |5665|3:3|reload| 2010-03-24
> > 17:39:29|5665|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.
> > |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> > |5665|3:3|reload| (-1) vcld, warning_handler (line: 636)
> > |5665|3:3|reload| (-2) esx.pm, load (line: 354)
> > |5665|3:3|reload| (-3) new.pm, reload_image (line: 665)
> > |5665|3:3|reload| (-4) new.pm, process (line: 266)
> > |5665|3:3|reload| (-5) vcld, make_new_child (line: 594)
> > |5665|3:3|reload| (-6) vcld, main (line: 341)
> >
> > 2010-03-24 17:39:29|5665|3:3|reload|esx.pm:load(376)|wrote vmxarray to
> > /tmp/esx3-basewinxp-v0.vmx
> > 2010-03-24 17:39:29|5665|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/esx3-basewinxp-v0.vmx 192.168.129.37:
> /install/image/vmware_images/inuse/esx3-basewinxp-v0/esx3-basewinxp-v0.vmx
> > 2>&1
> > 2010-03-24 17:39:29|5665|3:3|reload|utils.pm:run_scp_command(6453)|scp
> > successful: attempt 1/3, exit status: 0, output: none
> > 2010-03-24 17:39:29|5665|3:3|reload|esx.pm:load(401)|Register Command:
> > /usr/lib/vmware-vcli/apps/vm/vmregister.pl --server 'esx35-hypervisor-1'
> > --username root --password 'xxxxxxxxxxx' --vmxpath
> > '[VCL]/inuse/esx3-basewinxp-v0/esx3-basewinxp-v0.vmx' --operation
> register
> > --vmname esx3-basewinxp-v0 --pool Resources --hostname '
> > esx35-hypervisor-1.odu.edu' --datacenter 'ha-datacenter'
> > 2010-03-24 17:39:33|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:39:33
> > 2010-03-24 17:39:38|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:39:38
> > 2010-03-24 17:39:43|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:39:43
> > 2010-03-24 17:39:48|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:39:48
> > 2010-03-24 17:39:53|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:39:53
> > 2010-03-24 17:39:58|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:39:58
> > 2010-03-24 17:40:03|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:40:03
> > 2010-03-24 17:40:08|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:40:08
> > 2010-03-24 17:40:13|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:40:13
> > 2010-03-24 17:40:18|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:40:18
> > 2010-03-24 17:40:23|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:40:23
> > 2010-03-24 17:40:28|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:40:28
> > 2010-03-24 17:40:32|5665|3:3|reload|esx.pm:load(404)|Registered:
> > |5665|3:3|reload| Register of VM 'esx3-basewinxp-v0' successfully
> completed
> > under host esx35-hypervisor-1.odu.edu
> > 2010-03-24 17:40:32|5665|3:3|reload|esx.pm:load(413)|Power on command:
> > /usr/lib/vmware-vcli/apps/vm/vmcontrol.pl --server 'esx35-hypervisor-1'
> > --vmname esx3-basewinxp-v0 --operation poweron --username root --password
> > 'xxxxxxxxxxx'
> > 2010-03-24 17:40:33|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:40:33
> > 2010-03-24 17:40:33|5665|3:3|reload|esx.pm:load(416)|Powered on: Virtual
> > Machine esx3-basewinxp-v0 not found.
> > 2010-03-24 17:40:33|5665|3:3|reload|esx.pm:load(505)|IP is known for
> > esx3-basewinxp-v0
> > 2010-03-24 17:40:33|5665|3:3|reload|esx.pm:load(511)|Waiting for ssh to
> > come up on esx3-basewinxp-v0
> > 2010-03-24 17:40:34|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 1
> > 2010-03-24 17:40:38|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:40:38
> > 2010-03-24 17:40:40|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 2
> > 2010-03-24 17:40:43|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:40:43
> > 2010-03-24 17:40:46|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 3
> > 2010-03-24 17:40:48|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:40:48
> > 2010-03-24 17:40:52|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 4
> > 2010-03-24 17:40:53|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:40:53
> > 2010-03-24 17:40:58|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:40:58
> > 2010-03-24 17:40:58|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 5
> > 2010-03-24 17:41:03|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:41:03
> > 2010-03-24 17:41:04|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 6
> > 2010-03-24 17:41:08|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:41:08
> > 2010-03-24 17:41:10|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 7
> > 2010-03-24 17:41:13|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:41:13
> > 2010-03-24 17:41:16|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 8
> > 2010-03-24 17:41:18|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:41:18
> > 2010-03-24 17:41:22|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 9
> > 2010-03-24 17:41:23|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:41:23
> > 2010-03-24 17:41:28|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:41:28
> > 2010-03-24 17:41:28|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 10
> > 2010-03-24 17:41:33|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:41:33
> > 2010-03-24 17:41:34|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 11
> > 2010-03-24 17:41:38|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:41:38
> > 2010-03-24 17:41:41|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 12
> > 2010-03-24 17:41:43|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:41:43
> > 2010-03-24 17:41:47|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 13
> > 2010-03-24 17:41:49|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:41:48
> > 2010-03-24 17:41:53|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 14
> > 2010-03-24 17:41:54|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:41:54
> > 2010-03-24 17:41:59|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:41:59
> > 2010-03-24 17:41:59|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 15
> > 2010-03-24 17:42:04|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:42:04
> > 2010-03-24 17:42:05|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 16
> > 2010-03-24 17:42:09|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:42:09
> > 2010-03-24 17:42:11|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 17
> > 2010-03-24 17:42:14|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:42:14
> > 2010-03-24 17:42:17|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 18
> > 2010-03-24 17:42:19|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:42:19
> > 2010-03-24 17:42:23|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 19
> > 2010-03-24 17:42:24|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:42:24
> > 2010-03-24 17:42:29|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 20
> > 2010-03-24 17:42:29|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:42:29
> > 2010-03-24 17:42:34|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:42:34
> > 2010-03-24 17:42:35|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 21
> > 2010-03-24 17:42:39|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:42:39
> > 2010-03-24 17:42:41|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 22
> > 2010-03-24 17:42:44|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:42:44
> > 2010-03-24 17:42:47|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 23
> > 2010-03-24 17:42:49|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:42:49
> > 2010-03-24 17:42:53|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 24
> > 2010-03-24 17:42:54|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:42:54
> > 2010-03-24 17:42:59|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 25
> > 2010-03-24 17:42:59|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:42:59
> > 2010-03-24 17:43:04|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:43:04
> > 2010-03-24 17:43:05|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 26
> > 2010-03-24 17:43:09|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:43:09
> > 2010-03-24 17:43:11|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 27
> > 2010-03-24 17:43:14|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:43:14
> > 2010-03-24 17:43:17|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 28
> > 2010-03-24 17:43:19|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:43:19
> > 2010-03-24 17:43:23|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 29
> > 2010-03-24 17:43:24|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:43:24
> > 2010-03-24 17:43:29|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 30
> > 2010-03-24 17:43:29|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:43:29
> > 2010-03-24 17:43:34|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:43:34
> > 2010-03-24 17:43:35|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 31
> > 2010-03-24 17:43:39|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:43:39
> > 2010-03-24 17:43:41|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 32
> > 2010-03-24 17:43:44|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:43:44
> > 2010-03-24 17:43:47|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 33
> > 2010-03-24 17:43:49|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:43:49
> > 2010-03-24 17:43:53|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 34
> > 2010-03-24 17:43:54|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:43:54
> > 2010-03-24 17:43:59|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 35
> > 2010-03-24 17:43:59|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:43:59
> > 2010-03-24 17:44:04|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:44:04
> > 2010-03-24 17:44:05|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 36
> > 2010-03-24 17:44:09|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:44:09
> > 2010-03-24 17:44:11|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 37
> > 2010-03-24 17:44:14|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:44:14
> > 2010-03-24 17:44:17|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 38
> > 2010-03-24 17:44:19|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:44:19
> > 2010-03-24 17:44:23|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 39
> > 2010-03-24 17:44:24|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:44:24
> > 2010-03-24 17:44:29|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 40
> > 2010-03-24 17:44:29|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:44:29
> > 2010-03-24 17:44:35|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:44:34
> > 2010-03-24 17:44:35|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 41
> > 2010-03-24 17:44:40|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:44:40
> > 2010-03-24 17:44:41|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 42
> > 2010-03-24 17:44:45|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:44:45
> > 2010-03-24 17:44:47|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 43
> > 2010-03-24 17:44:50|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:44:50
> > 2010-03-24 17:44:53|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 44
> > 2010-03-24 17:44:55|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:44:55
> > 2010-03-24 17:44:59|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 45
> > 2010-03-24 17:45:00|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:45:00
> > 2010-03-24 17:45:05|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:45:05
> > 2010-03-24 17:45:05|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 46
> > 2010-03-24 17:45:10|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:45:10
> > 2010-03-24 17:45:11|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 47
> > 2010-03-24 17:45:15|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:45:15
> > 2010-03-24 17:45:17|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 48
> > 2010-03-24 17:45:20|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:45:20
> > 2010-03-24 17:45:23|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 49
> > 2010-03-24 17:45:25|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:45:25
> > 2010-03-24 17:45:29|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 50
> > 2010-03-24 17:45:30|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:45:30
> > 2010-03-24 17:45:35|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:45:35
> > 2010-03-24 17:45:35|5665|3:3|reload|esx.pm:load(528)|going to sleep 5
> > seconds, waiting for computer to start SSH. Try 51
> > 2010-03-24 17:45:40|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:45:40
> > No recipient addresses found in header
> > 2010-03-24 17:45:45|5665|3:3|reload|utils.pm:mail(1348)|SUCCESS --
> Sending
> > mail To: , PROBLEM -- esx.pm
> >
> > |5665|3:3|reload| ---- CRITICAL ----
> > |5665|3:3|reload| 2010-03-24 17:45:41|5665|3:3|reload|esx.pm:
> load(521)|waited
> > acceptable amount of time for sshd to become active, please check
> > esx3-basewinxp-v0 on esx35-hypervisor-1
> > |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> > |5665|3:3|reload| (-1) esx.pm, load (line: 521)
> > |5665|3:3|reload| (-2) new.pm, reload_image (line: 665)
> > |5665|3:3|reload| (-3) new.pm, process (line: 266)
> > |5665|3:3|reload| (-4) vcld, make_new_child (line: 594)
> > |5665|3:3|reload| (-5) vcld, main (line: 341)
> >
> >
> > |5665|3:3|reload| ---- WARNING ----
> > |5665|3:3|reload| 2010-03-24 17:45:45|5665|3:3|reload|new.pm:
> reload_image(670)|esx3-basewinxp-v0
> > failed to load on esx3-basewinxp-v0, returning
> > |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> > |5665|3:3|reload| (-1) new.pm, reload_image (line: 670)
> > |5665|3:3|reload| (-2) new.pm, process (line: 266)
> > |5665|3:3|reload| (-3) vcld, make_new_child (line: 594)
> > |5665|3:3|reload| (-4) vcld, main (line: 341)
> >
> > 2010-03-24 17:45:45|5665|3:3|reload|utils.pm:
> insertloadlog(4710)|inserted
> > computer=3, loadimagefailed, esx3-basewinxp-v0 failed to load on
> > esx3-basewinxp-v0
> >
> > |5665|3:3|reload| ---- WARNING ----
> > |5665|3:3|reload| 2010-03-24 17:45:45|5665|3:3|reload|new.pm:
> process(313)|failed
> > to load esx3-basewinxp-v0 with esx3-basewinxp-v0
> > |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> > |5665|3:3|reload| (-1) new.pm, process (line: 313)
> > |5665|3:3|reload| (-2) vcld, make_new_child (line: 594)
> > |5665|3:3|reload| (-3) vcld, main (line: 341)
> >
> > 2010-03-24
> >
> 17:45:45|5665|3:3|reload|DataStructure.pm:get_computer_state_name(1946)|attempting
> > to retrieve current state of computer esx3-basewinxp-v0 from the database
> > 2010-03-24
> >
> 17:45:45|5665|3:3|reload|DataStructure.pm:get_computer_state_name(1977)|retrieved
> > current state of computer esx3-basewinxp-v0 from the database: reloading
> > 2010-03-24
> 17:45:45|5665|3:3|reload|DataStructure.pm:_automethod(697)|data
> > structure updated:
> > $self->request_data->{reservation}{3}{computer}{state}{name}
> > |5665|3:3|reload| computer_state_name = reloading
> > No recipient addresses found in header
> > 2010-03-24 17:45:45|5665|3:3|reload|utils.pm:mail(1348)|SUCCESS --
> Sending
> > mail To: , PROBLEM -- State.pm
> >
> > |5665|3:3|reload| ---- CRITICAL ----
> > |5665|3:3|reload| 2010-03-24
> > 17:45:45|5665|3:3|reload|State.pm:reservation_failed(290)|reservation
> failed
> > on esx3-basewinxp-v0: process failed after trying to load or make
> available
> > |5665|3:3|reload| ( 0) utils.pm, notify (line: 737)
> > |5665|3:3|reload| (-1) State.pm, reservation_failed (line: 290)
> > |5665|3:3|reload| (-2) new.pm, process (line: 316)
> > |5665|3:3|reload| (-3) vcld, make_new_child (line: 594)
> > |5665|3:3|reload| (-4) vcld, main (line: 341)
> >
> > 2010-03-24 17:45:45|5665|3:3|reload|utils.pm:
> insertloadlog(4710)|inserted
> > computer=3, failed, process failed after trying to load or make available
> > 2010-03-24
> > 17:45:45|5665|3:3|reload|State.pm:reservation_failed(293)|inserted
> > computerloadlog entry
> > 2010-03-24 17:45:45|5665|3:3|reload|utils.pm:
> update_computer_state(2228)|computer
> > 3 state updated to: failed
> > 2010-03-24
> > 17:45:45|5665|3:3|reload|State.pm:reservation_failed(312)|computer
> > esx3-basewinxp-v0 (3) state set to failed
> > 2010-03-24 17:45:45|5665|3:3|reload|utils.pm:
> update_request_state(2186)|request
> > 3 state updated to: failed, laststate to: image
> > 2010-03-24 17:45:45|5665|3:3|reload|State.pm:reservation_failed(325)|set
> > request state to 'failed'/'image'
> > 2010-03-24 17:45:45|5665|3:3|reload|utils.pm:
> is_inblockrequest(6972)|zero
> > rows were returned from database select
> > 2010-03-24
> >
> 17:45:45|5665|3:3|reload|State.pm:reservation_failed(343)|esx3-basewinxp-v0
> > is NOT in blockcomputers table
> > 2010-03-24
> > 17:45:45|5665|3:3|reload|State.pm:reservation_failed(346)|exiting 1
> > 2010-03-24 17:45:45|5665|3:3|reload|State.pm:DESTROY(905)|destructor
> > called, ref($self)=VCL::new
> > 2010-03-24 17:45:45|5665|3:3|reload|utils.pm:
> delete_computerloadlog_reservation(7551)|removing
> > computerloadlog entries matching loadstate = begin
> > 2010-03-24 17:45:45|5665|3:3|reload|utils.pm:
> delete_computerloadlog_reservation(7598)|deleted
> > rows from computerloadlog for reservation id=3
> > 2010-03-24 17:45:45|5665|3:3|reload|State.pm:DESTROY(912)|removed
> > computerloadlog rows with loadstate=begin for reservation
> > 2010-03-24 17:45:45|5665|3:3|reload|State.pm:DESTROY(924)|number of
> > database handles state process created: 1
> > 2010-03-24 17:45:45|5665|3:3|reload|State.pm:DESTROY(933)|process has a
> > database handle stored in $ENV{dbh}, attempting disconnect
> > 2010-03-24 17:45:45|5665|3:3|reload|State.pm:DESTROY(935)|$ENV{dbh}:
> > database disconnect successful
> > 2010-03-24 17:45:45|5665|3:3|reload|State.pm:DESTROY(949)|VCL::new
> process
> > 5665 exiting
> > 2010-03-24 17:45:45|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:45:45
> > 2010-03-24 17:45:45|5443|3:3|failed|vcld:main(250)|request deleted
> > 2010-03-24 17:45:45|5443|vcld:REAPER(744)|VCL process exited for
> > reservation 3
> > 2010-03-24 17:45:45|5443|vcld:main(165)|lastcheckin time updated for
> > management node 1: 2010-03-24 17:45:45
> >
> >
> > Thank you,
> > Amit
> >
> >
>