Here is the extended log file as promised. Best, Kris Augustus CCNA, RHCE, A+ Lab Supervisor College of TECS East Carolina University 252-737-1978 august...@ecu.edu<mailto:august...@ecu.edu>
Intelligence plus character- that is the goal of true education. Dr. Martin Luther King Jr.
2009-05-14 17:31:03|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:31:03 2009-05-14 17:31:15|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:31:15 2009-05-14 17:31:20|5506|33:33|new|utils.pm:run_ssh_command(6776)|run_ssh_command output: 2009-05-14 17:31:20|5506|33:33|new|utils.pm:run_ssh_command(6784)|SSH command executed on 172.17.0.1, returning (0, "none") 2009-05-14 17:31:20|5506|33:33|new|utils.pm:run_ssh_command(6695)|executing SSH command on 172.17.0.1: 2009-05-14 17:31:21|5506|33:33|new|utils.pm:run_ssh_command(6776)|run_ssh_command output: 2009-05-14 17:31:21|5506|33:33|new|utils.pm:run_ssh_command(6784)|SSH command executed on 172.17.0.1, returning (0, "ddb.adapterType = "lsilogic"") 2009-05-14 17:31:21|5506|33:33|new|esx.pm:load(266)|adapter= lsilogic 2009-05-14 17:31:21|5506|33:33|new|esx.pm:load(311)|wrote vmxarray to /tmp/TECS-ESX-4600-2.vmx 2009-05-14 17:31:21|5506|33:33|new|utils.pm:run_scp_command(6896)|attempt 1/3: executing SCP command: /usr/bin/scp -B -i /etc/vcl/bladelinuxkey_id_rsa -P 22 -p -r /tmp/TECS-ESX-4600-2.vmx 172.17.0.1:/mnt/vcl/inuse/TECS-ESX-4600-2/esx3-linuxtest-v0.vmx 2>&1 2009-05-14 17:31:21|5506|33:33|new|utils.pm:run_scp_command(6942)|scp successful: attempt 1/3, exit status: 0, output: none 2009-05-14 17:31:21|5506|33:33|new|esx.pm:load(336)|Register Command: /usr/lib/vmware-viperl/apps/vm/vmregister.pl --server 'TECS-ESX-4600-2' --username vcl --password 'xxxxxxxx' --vmxpath '[VCL]/inuse/TECS-ESX-4600-2/esx3-linuxtest-v0.vmx' --operation register --vmname TECS-ESX-4600-2 --pool Resources --hostname 'TECS-ESX-4600-2' --datacenter 'ha-datacenter' 2009-05-14 17:31:27|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:31:27 2009-05-14 17:31:29|5506|33:33|new|esx.pm:load(339)|Registered: 2009-05-14 17:31:29|5506|33:33|new|esx.pm:load(348)|Power on command: /usr/lib/vmware-viperl/apps/vm/vmcontrol.pl --server 'TECS-ESX-4600-2' --vmname TECS-ESX-4600-2 --operation poweron --username vcl --password 'xxxxxxxx' 2009-05-14 17:31:36|5506|33:33|new|esx.pm:load(351)|Powered on: Virtual Machine TECS-ESX-4600-2 not found. 2009-05-14 17:31:39|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:31:39 2009-05-14 17:31:44|5506|33:33|new|utils.pm:mail(1301)|SUCCESS -- Sending mail To: , PROBLEM -- esx.pm |5506|33:33|new| 2009-05-14 17:31:44|5506|33:33|new|esx.pm:load(359)|Could not query for VM in VI PERL API |5506|33:33|new| 2009-05-14 17:31:44|5506|33:33|new|new.pm:reload_image(669)|esx3-linuxtest-v0 failed to load on TECS-ESX-4600-2, returning 2009-05-14 17:31:44|5506|33:33|new|utils.pm:insertloadlog(5324)|inserted computer=1, loadimagefailed, esx3-linuxtest-v0 failed to load on TECS-ESX-4600-2 |5506|33:33|new| 2009-05-14 17:31:44|5506|33:33|new|new.pm:process(313)|failed to load TECS-ESX-4600-2 with esx3-linuxtest-v0 2009-05-14 17:31:44|5506|33:33|new|utils.pm:mail(1301)|SUCCESS -- Sending mail To: , PROBLEM -- State.pm |5506|33:33|new| 2009-05-14 17:31:44|5506|33:33|new|State.pm:reservation_failed(285)|reservation failed on TECS-ESX-4600-2: process failed after trying to load or make available 2009-05-14 17:31:44|5506|33:33|new|utils.pm:insertloadlog(5324)|inserted computer=1, failed, process failed after trying to load or make available 2009-05-14 17:31:44|5506|33:33|new|State.pm:reservation_failed(288)|inserted computerloadlog entry 2009-05-14 17:31:44|5506|33:33|new|State.pm:reservation_failed(296)|updated log ending value to 'failed', logid=18 2009-05-14 17:31:44|5506|33:33|new|utils.pm:update_computer_state(2325)|computer 1 state updated to: failed 2009-05-14 17:31:44|5506|33:33|new|State.pm:reservation_failed(307)|computer TECS-ESX-4600-2 (1) state set to failed 2009-05-14 17:31:44|5506|33:33|new|utils.pm:update_request_state(2283)|request 33 state updated to: failed, laststate to: new 2009-05-14 17:31:44|5506|33:33|new|State.pm:reservation_failed(315)|set request state to 'failed'/'new' 2009-05-14 17:31:44|5506|33:33|new|utils.pm:is_inblockrequest(7384)|zero rows were returned from database select 2009-05-14 17:31:44|5506|33:33|new|State.pm:reservation_failed(333)|TECS-ESX-4600-2 is NOT in blockcomputers table 2009-05-14 17:31:44|5506|33:33|new|State.pm:reservation_failed(336)|exiting 1 2009-05-14 17:31:44|5506|33:33|new|State.pm:DESTROY(442)|destructor called, ref($self)=VCL::new 2009-05-14 17:31:44|5506|33:33|new|utils.pm:delete_computerloadlog_reservation(8041)|removing computerloadlog entries matching loadstate = begin 2009-05-14 17:31:44|5506|33:33|new|utils.pm:delete_computerloadlog_reservation(8088)|deleted rows from computerloadlog for reservation id=33 2009-05-14 17:31:44|5506|33:33|new|State.pm:DESTROY(445)|removed computerloadlog rows with loadstate=begin for reservation 2009-05-14 17:31:44|5506|33:33|new|State.pm:DESTROY(453)|number of database handles state process created: 1 2009-05-14 17:31:44|5506|33:33|new|State.pm:DESTROY(462)|process has a database handle stored in $ENV{dbh}, attempting disconnect 2009-05-14 17:31:44|5506|33:33|new|State.pm:DESTROY(464)|$ENV{dbh}: database disconnect successful 2009-05-14 17:31:44|2065|vcld:REAPER(750)|VCL process exited for reservation 33 2009-05-14 17:31:44|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:31:44 2009-05-14 17:31:56|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:31:56 2009-05-14 17:32:08|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:32:08 2009-05-14 17:32:20|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:32:20 2009-05-14 17:32:32|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:32:32 2009-05-14 17:32:44|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:32:44 2009-05-14 17:32:57|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:32:57 2009-05-14 17:33:09|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:33:09 2009-05-14 17:33:21|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:33:21 2009-05-14 17:33:33|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:33:33 2009-05-14 17:33:45|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:33:45 2009-05-14 17:33:57|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:33:57 2009-05-14 17:34:09|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:34:09 2009-05-14 17:34:21|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:34:21 2009-05-14 17:34:33|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:34:33 2009-05-14 17:34:45|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:34:45 2009-05-14 17:34:57|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:34:57 2009-05-14 17:35:09|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:35:09 2009-05-14 17:35:21|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:35:21 2009-05-14 17:35:33|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:35:33 2009-05-14 17:35:45|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:35:45 2009-05-14 17:35:57|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:35:57 2009-05-14 17:36:09|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:36:09 2009-05-14 17:36:21|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:36:21 2009-05-14 17:36:33|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:36:33 2009-05-14 17:36:45|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:36:45 2009-05-14 17:36:57|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:36:57 2009-05-14 17:37:09|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:37:09 2009-05-14 17:37:21|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:37:21 2009-05-14 17:37:33|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:37:33 2009-05-14 17:37:45|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:37:45 2009-05-14 17:37:57|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:37:57 2009-05-14 17:38:09|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:38:09 2009-05-14 17:38:21|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:38:21 2009-05-14 17:38:33|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:38:33 2009-05-14 17:38:45|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:38:45 2009-05-14 17:38:57|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:38:57 2009-05-14 17:39:10|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:39:09 2009-05-14 17:39:22|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:39:22 2009-05-14 17:39:34|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:39:34 2009-05-14 17:39:46|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:39:46 2009-05-14 17:39:58|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:39:58 2009-05-14 17:40:10|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:40:10 2009-05-14 17:40:22|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:40:22 2009-05-14 17:40:34|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:40:34 2009-05-14 17:40:46|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:40:46 2009-05-14 17:40:58|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:40:58 2009-05-14 17:41:10|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:41:10 2009-05-14 17:41:22|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:41:22 2009-05-14 17:41:34|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:41:34 2009-05-14 17:41:46|2065|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:41:46 OUTPUT for vcld run on 2009-05-14 17:41:56 2009-05-14 17:41:56|6209|vcld:main(117)|vcld environment variable set to 1 for this process 2009-05-14 17:41:56|6209|utils.pm:rename_vcld_process(8390)|renamed process to 'vcld vcld' 2009-05-14 17:41:56|6209|utils.pm:get_management_node_info(7277)|management node info retrieved from database for 150 2009-05-14 17:41:56|6209|vcld:main(128)|retrieved management node information from database 2009-05-14 17:41:56|6209|vcld:main(141)|management_node_id environment variable set: 1 2009-05-14 17:41:56|6209|vcld:main(149)|management node checkin interval is 12 seconds 2009-05-14 17:41:56|6209|vcld:main(150)|vcld started on 150.xxx.xxx.186 OUTPUT for vcld run on 2009-05-14 17:42:25 2009-05-14 17:42:25|6380|vcld:main(117)|vcld environment variable set to 1 for this process 2009-05-14 17:42:25|6380|utils.pm:rename_vcld_process(8390)|renamed process to 'vcld vcld' 2009-05-14 17:42:25|6380|utils.pm:get_management_node_info(7277)|management node info retrieved from database for 150 2009-05-14 17:42:25|6380|vcld:main(128)|retrieved management node information from database 2009-05-14 17:42:25|6380|vcld:main(141)|management_node_id environment variable set: 1 2009-05-14 17:42:25|6380|vcld:main(149)|management node checkin interval is 12 seconds 2009-05-14 17:42:25|6380|vcld:main(150)|vcld started on 150.xxx.xxx.186 2009-05-14 17:42:37|6380|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:42:37 2009-05-14 17:42:49|6380|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:42:49 2009-05-14 17:43:01|6380|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:43:01 2009-05-14 17:43:14|6380|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:43:14 2009-05-14 17:43:14|6380|34:34|new|utils.pm:check_time(1167)|reservation start time was in the past 17 minutes (-13) 2009-05-14 17:43:14|6380|34:34|new|utils.pm:reservation_being_processed(9818)|computerloadlog 'begin' entry does NOT exist for reservation 34 2009-05-14 17:43:14|6380|34:34|new|utils.pm:reservation_being_processed(9870)|reservation is NOT currently being processed 2009-05-14 17:43:14|6380|34:34|new|vcld:main(282)|reservation 34 is NOT already being processed |6380|34:34|new| 2009-05-14 17:43:14|6380|34:34|new|utils.pm:get_request_info(5845)|preferredimageid is not set for computer id=1 2009-05-14 17:43:14|6380|34:34|new|utils.pm:get_request_info(5991)|non-NCSU user affiliation found: Local 2009-05-14 17:43:14|6380|34:34|new|utils.pm:get_management_node_info(7277)|management node info retrieved from database for 150 2009-05-14 17:43:14|6380|34:34|new|vcld:main(287)|retrieved request information from database 2009-05-14 17:43:14|6380|34:34|new|utils.pm:get_management_node_info(7277)|management node info retrieved from database for 150 2009-05-14 17:43:14|6380|34:34|new|DataStructure.pm:is_parent_reservation(785)|returning true: parent reservation ID for this request: 34 2009-05-14 17:43:14|6380|34:34|new|utils.pm:update_request_state(2283)|request 34 state updated to: pending, laststate to: new 2009-05-14 17:43:14|6380|34:34|new|vcld:main(327)|request state updated to pending, laststate new 2009-05-14 17:43:14|6380|34:34|new|utils.pm:insertloadlog(5324)|inserted computer=1, begin, beginning to process, state is new 2009-05-14 17:43:14|6380|34:34|new|vcld:main(340)|inserted 'begin' entry into computerloadlog for reservation 34 2009-05-14 17:43:14|6380|34:34|new|vcld:make_new_child(511)|creating new process 2009-05-14 17:43:14|6380|34:34|new|vcld:make_new_child(515)|loaded VCL::new module 2009-05-14 17:43:14|6423|34:34|new|vcld:make_new_child(588)|vcld environment variable set to 0 for this process 2009-05-14 17:43:14|6423|34:34|new|Module.pm:new(80)|constructor called, class=VCL::new 2009-05-14 17:43:14|6423|34:34|new|Module.pm:new(102)|VCL::new object created 2009-05-14 17:43:14|6380|34:34|new|vcld:make_new_child(572)|current number of forked kids: 1 2009-05-14 17:43:14|6423|34:34|new|State.pm:initialize(86)|obtained a database handle for this state process, stored as $ENV{dbh} 2009-05-14 17:43:14|6423|34:34|new|State.pm:check_image_os(361)|no corrections need to be made, not an imaging request, returning 1 2009-05-14 17:43:14|6423|34:34|new|DataStructure.pm:is_parent_reservation(785)|returning true: parent reservation ID for this request: 34 2009-05-14 17:43:14|6423|34:34|new|utils.pm:rename_vcld_process(8352)|reservation count: 1 2009-05-14 17:43:14|6423|34:34|new|utils.pm:rename_vcld_process(8371)|PARENTIMAGE: 1 2009-05-14 17:43:14|6423|34:34|new|utils.pm:rename_vcld_process(8372)|SUBIMAGE: 0 2009-05-14 17:43:14|6423|34:34|new|utils.pm:rename_vcld_process(8390)|renamed process to 'vcld VCL::new 34:34 new' 2009-05-14 17:43:14|6423|34:34|new|DataStructure.pm:is_parent_reservation(785)|returning true: parent reservation ID for this request: 34 2009-05-14 17:43:14|6423|34:34|new|DataStructure.pm:is_parent_reservation(785)|returning true: parent reservation ID for this request: 34 2009-05-14 17:43:14|6423|34:34|new|State.pm:initialize(122)|attempting to load provisioning module: VCL::Module::Provisioning::esx 2009-05-14 17:43:14|6423|34:34|new|esx.pm:initialize(117)|vmware ESX module initialized 2009-05-14 17:43:14|6423|34:34|new|State.pm:initialize(129)|VCL::Module::Provisioning::esx module successfully loaded 2009-05-14 17:43:14|6423|34:34|new|Module.pm:new(80)|constructor called, class=VCL::Module::Provisioning::esx 2009-05-14 17:43:14|6423|34:34|new|Module.pm:new(102)|VCL::Module::Provisioning::esx object created 2009-05-14 17:43:14|6423|34:34|new|esx.pm:initialize(117)|vmware ESX module initialized 2009-05-14 17:43:14|6423|34:34|new|State.pm:initialize(133)|VCL::Module::Provisioning::esx provisioner object successfully created 2009-05-14 17:43:14|6423|34:34|new|State.pm:initialize(147)|attempting to load OS module: VCL::Module::OS::Linux 2009-05-14 17:43:14|6423|34:34|new|Module.pm:new(80)|constructor called, class=VCL::Module::OS::Linux 2009-05-14 17:43:14|6423|34:34|new|Module.pm:new(102)|VCL::Module::OS::Linux object created 2009-05-14 17:43:14|6423|34:34|new|State.pm:initialize(155)|VCL::Module::OS::Linux OS object successfully created 2009-05-14 17:43:14|6423|34:34|new|State.pm:initialize(170)|returning 1 2009-05-14 17:43:14|6423|34:34|new|vcld:make_new_child(597)|VCL::new object created and initialized 2009-05-14 17:43:14|6423|34:34|new|DataStructure.pm:is_parent_reservation(785)|returning true: parent reservation ID for this request: 34 |6423|34:34|new| 2009-05-14 17:43:14|6423|34:34|new|DataStructure.pm:_automethod(610)|corresponding data has not been initialized for get_computer_preferredimage_id: $self->request_data->{reservation}{34}{computer}{preferredimage}{id} |6423|34:34|new| 2009-05-14 17:43:14|6423|34:34|new|DataStructure.pm:_automethod(610)|corresponding data has not been initialized for get_computer_preferredimage_name: $self->request_data->{reservation}{34}{computer}{preferredimage}{name} 2009-05-14 17:43:14|6423|34:34|new|utils.pm:get_management_node_id(9383)|environment variable: 1 2009-05-14 17:43:14|6423|34:34|new|new.pm:process(135)|reservation is parent = 1 2009-05-14 17:43:14|6423|34:34|new|new.pm:process(136)|preload only = 0 2009-05-14 17:43:14|6423|34:34|new|new.pm:process(137)|originating request state = new 2009-05-14 17:43:14|6423|34:34|new|new.pm:process(138)|originating request laststate = new 2009-05-14 17:43:14|6423|34:34|new|new.pm:process(139)|originating computer state = available 2009-05-14 17:43:14|6423|34:34|new|new.pm:process(140)|originating computer type = blade 2009-05-14 17:43:14|6423|34:34|new|DataStructure.pm:is_parent_reservation(785)|returning true: parent reservation ID for this request: 34 |6423|34:34|new| 2009-05-14 17:43:14|6423|34:34|new|DataStructure.pm:_automethod(610)|corresponding data has not been initialized for get_computer_preferredimage_id: $self->request_data->{reservation}{34}{computer}{preferredimage}{id} |6423|34:34|new| 2009-05-14 17:43:14|6423|34:34|new|DataStructure.pm:_automethod(610)|corresponding data has not been initialized for get_computer_preferredimage_name: $self->request_data->{reservation}{34}{computer}{preferredimage}{name} 2009-05-14 17:43:14|6423|34:34|new|utils.pm:get_management_node_id(9383)|environment variable: 1 2009-05-14 17:43:14|6423|34:34|new|new.pm:computer_not_being_used(779)|TECS-ESX-4600-2 state is available 2009-05-14 17:43:14|6423|34:34|new|new.pm:computer_not_being_used(789)|TECS-ESX-4600-2 is available, its state is available 2009-05-14 17:43:14|6423|34:34|new|new.pm:process(170)|TECS-ESX-4600-2 is not being used 2009-05-14 17:43:14|6423|34:34|new|DataStructure.pm:is_parent_reservation(785)|returning true: parent reservation ID for this request: 34 |6423|34:34|new| 2009-05-14 17:43:14|6423|34:34|new|DataStructure.pm:_automethod(610)|corresponding data has not been initialized for get_computer_preferredimage_id: $self->request_data->{reservation}{34}{computer}{preferredimage}{id} |6423|34:34|new| 2009-05-14 17:43:14|6423|34:34|new|DataStructure.pm:_automethod(610)|corresponding data has not been initialized for get_computer_preferredimage_name: $self->request_data->{reservation}{34}{computer}{preferredimage}{name} 2009-05-14 17:43:14|6423|34:34|new|utils.pm:get_management_node_id(9383)|environment variable: 1 2009-05-14 17:43:14|6423|34:34|new|new.pm:reload_image(513)|calling VCL::Module::Provisioning::esx->node_status() 2009-05-14 17:43:14|6423|34:34|new|utils.pm:insertloadlog(5324)|inserted computer=1, statuscheck, checking status of node 2009-05-14 17:43:14|6423|34:34|new|esx.pm:node_status(646)|Entering node_status, checking status of TECS-ESX-4600-2 2009-05-14 17:43:14|6423|34:34|new|esx.pm:node_status(647)|request_for_imaging: 0 2009-05-14 17:43:14|6423|34:34|new|esx.pm:node_status(648)|requeseted image name: esx3-linuxtest-v0 2009-05-14 17:43:14|6423|34:34|new|esx.pm:node_status(678)|checking if TECS-ESX-4600-2 is pingable 2009-05-14 17:43:14|6423|34:34|new|esx.pm:node_status(681)|TECS-ESX-4600-2 is pingable (1) 2009-05-14 17:43:14|6423|34:34|new|esx.pm:node_status(695)|Trying to ssh... 2009-05-14 17:43:14|6423|34:34|new|esx.pm:node_status(733)|status set to RELOAD 2009-05-14 17:43:14|6423|34:34|new|esx.pm:node_status(741)|returning node status hash reference ($node_status->{status}=RELOAD) 2009-05-14 17:43:14|6423|34:34|new|new.pm:reload_image(528)|node_status returned a hash reference 2009-05-14 17:43:14|6423|34:34|new|new.pm:reload_image(533)|node_status hash reference contains key {status}=RELOAD 2009-05-14 17:43:14|6423|34:34|new|new.pm:reload_image(601)|node status is RELOAD, TECS-ESX-4600-2 will be reloaded 2009-05-14 17:43:15|6423|34:34|new|utils.pm:insertloadlog(5324)|inserted computer=1, loadimageblade, TECS-ESX-4600-2 must be reloaded with esx3-linuxtest-v0 2009-05-14 17:43:15|6423|34:34|new|new.pm:reload_image(615)|calling VCL::Module::Provisioning::esx->does_image_exist() 2009-05-14 17:43:15|6423|34:34|new|utils.pm:run_ssh_command(6695)|executing SSH command on 172.17.0.1: 2009-05-14 17:43:15|6423|34:34|new|utils.pm:run_ssh_command(6776)|run_ssh_command output: 2009-05-14 17:43:15|6423|34:34|new|utils.pm:run_ssh_command(6784)|SSH command executed on 172.17.0.1, returning (0, "aquota.group aquota.user esx3-...") 2009-05-14 17:43:15|6423|34:34|new|esx.pm:does_image_exist(775)|image esx3-linuxtest-v0 exists 2009-05-14 17:43:15|6423|34:34|new|new.pm:reload_image(618)|esx3-linuxtest-v0 exists on this management node 2009-05-14 17:43:15|6423|34:34|new|utils.pm:insertloadlog(5324)|inserted computer=1, doesimageexists, confirmed image exists 2009-05-14 17:43:15|6423|34:34|new|utils.pm:update_computer_state(2325)|computer 1 state updated to: reloading 2009-05-14 17:43:15|6423|34:34|new|new.pm:reload_image(651)|computer TECS-ESX-4600-2 state set to reloading 2009-05-14 17:43:15|6423|34:34|new|utils.pm:insertloadlog(5324)|inserted computer=1, info, computer state updated to reloading 2009-05-14 17:43:15|6423|34:34|new|new.pm:reload_image(662)|calling VCL::Module::Provisioning::esx->load() subroutine 2009-05-14 17:43:15|6423|34:34|new|utils.pm:insertloadlog(5324)|inserted computer=1, info, calling VCL::Module::Provisioning::esx->load() subroutine 2009-05-14 17:43:15|6423|34:34|new|esx.pm:load(142)|**************************************************** |6423|34:34|new| 2009-05-14 17:43:15|6423|34:34|new|DataStructure.pm:_automethod(610)|corresponding data has not been initialized for get_computer_eth0_mac_address: $self->request_data->{reservation}{34}{computer}{eth0macaddress} |6423|34:34|new| 2009-05-14 17:43:15|6423|34:34|new|DataStructure.pm:_automethod(610)|corresponding data has not been initialized for get_computer_eth1_mac_address: $self->request_data->{reservation}{34}{computer}{eth1macaddress} 2009-05-14 17:43:15|6423|34:34|new|esx.pm:load(170)|DATASTORE IP is 172.17.0.1 and DATASTORE_SHARE_PATH is /mnt/vcl 2009-05-14 17:43:15|6423|34:34|new|esx.pm:load(171)|Entered ESX module, loading esx3-linuxtest-v0 on TECS-ESX-4600-2 (on TECS-ESX-4600-2) for reservation 34 2009-05-14 17:43:15|6423|34:34|new|esx.pm:load(172)|Datastore: 172.17.0.1:/mnt/vcl 2009-05-14 17:43:15|6423|34:34|new|esx.pm:load(183)|VM info command: /usr/lib/vmware-viperl/apps/vm/vminfo.pl --server 'TECS-ESX-4600-2' --vmname TECS-ESX-4600-2 --username vcl --password 'xxxxxxxx' 2009-05-14 17:43:23|6423|34:34|new|esx.pm:load(186)|VM info output: Virtual Machine TECS-ESX-4600-2 not found. 2009-05-14 17:43:23|6423|34:34|new|utils.pm:run_ssh_command(6695)|executing SSH command on 172.17.0.1: 2009-05-14 17:43:26|6380|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:43:26 2009-05-14 17:43:27|6423|34:34|new|utils.pm:run_ssh_command(6776)|run_ssh_command output: 2009-05-14 17:43:27|6423|34:34|new|utils.pm:run_ssh_command(6784)|SSH command executed on 172.17.0.1, returning (0, "none") 2009-05-14 17:43:27|6423|34:34|new|esx.pm:load(222)|Removed old vm folder 2009-05-14 17:43:27|6423|34:34|new|utils.pm:run_ssh_command(6695)|executing SSH command on 172.17.0.1: 2009-05-14 17:43:27|6423|34:34|new|utils.pm:run_ssh_command(6776)|run_ssh_command output: 2009-05-14 17:43:27|6423|34:34|new|utils.pm:run_ssh_command(6784)|SSH command executed on 172.17.0.1, returning (0, "none") 2009-05-14 17:43:27|6423|34:34|new|utils.pm:run_ssh_command(6695)|executing SSH command on 172.17.0.1: 2009-05-14 17:43:28|6423|34:34|new|utils.pm:run_ssh_command(6776)|run_ssh_command output: 2009-05-14 17:43:28|6423|34:34|new|utils.pm:run_ssh_command(6784)|SSH command executed on 172.17.0.1, returning (0, "none") 2009-05-14 17:43:28|6423|34:34|new|esx.pm:load(238)|COPIED VMDK SUCCESSFULLY 2009-05-14 17:43:28|6423|34:34|new|utils.pm:run_ssh_command(6695)|executing SSH command on 172.17.0.1: 2009-05-14 17:43:38|6380|vcld:main(166)|lastcheckin time updated for management node 1: 2009-05-14 17:43:38