Re: can't complete reservation

[William Robinson]

hi all, in an effort to determine why i could not complete a reservation, i decided to start over with a new image while double-checking the check list sent in a previous email.  i'm beginning to think something is off in my database (though i admit that i probably have passed the point where i can't see the forest for the trees) and now i cannot even pull an image.  i would appreciate a fresh perspective on this.  things i've tried since last post: -noticed vmware and management node times were not synced, so enabled ntp -discovered typo in host file in regards to management interfaces -created custom image profiles (for debugging purposes) thanks. will -------- Original Message -------- Subject: image capture failure (email) Date: Wed, 8 Aug 2012 15:44:00 -0400 From: w...@clemson.edu <w...@clemson.edu> To: William Robinson <w...@clemson.edu> From r...@vcl.palmetto.clemson.edu Wed Aug 8 15:37:20 2012 Return-Path: <r...@vcl.palmetto.clemson.edu> Date: Wed, 8 Aug 2012 15:37:20 -0400 Subject: PROBLEM -- localhost|10:10|image|vcld|vclvm0001-man0>vclhv01|vmwarewin7-win7x64_base3-v0|admin To: w...@clemson.edu From: r...@vcl.palmetto.clemson.edu VCL::image object could not be created and initialized ------------------------------------------------------------------------ time: 2012-08-08 15:37:20 caller: vcld:make_new_child(574) ( 0) vcld, make_new_child (line: 574) (-1) vcld, main (line: 350) ------------------------------------------------------------------------ management node: localhost reservation PID: 7443 parent vcld PID: 23029 request ID: 10 reservation ID: 10 request state/laststate: image/image request start time: 2012-08-08 15:36:54 request end time: 2012-08-08 16:36:54 for imaging: no log ID: none computer: vclvm0001-man0 computer id: 6 computer type: virtualmachine computer eth0 MAC address: 00:50:56:00:00:01 computer eth1 MAC address: 00:50:56:00:00:02 computer private IP address: 10.128.64.100 computer public IP address: 10.128.64.200 computer in block allocation: no provisioning module: VCL::Module::Provisioning::VMware::VMware vm host: vclhv01 vm host ID: 1 vm host computer ID: 1 vm profile: VMware ESXi - double disk vm profile VM path: /vmfs/volumes/datastore2 vm profile repository path: <undefined> vm profile datastore path: /vmfs/volumes/datastore2 vm profile disk type: dedicated image: vmwarewin7-win7x64_base3-v0 image display name: win7-x64_base image ID: 3 image revision ID: 3 image size: 1450 MB use Sysprep: no root access: yes image owner ID: 1 image owner affiliation: Local image revision date created: 2012-08-08 15:36:54 image revision production: yes OS module: VCL::Module::OS::Windows::Version_6::7 user: admin user name: vcl admin user ID: 1 user affiliation: Local ------------------------------------------------------------------------ RECENT LOG ENTRIES FOR THIS PROCESS: 2012-08-08 15:36:54|7443|10:10|image|vcld:make_new_child(558)|vcld environment variable set to 0 for this process 2012-08-08 15:36:54|7443|10:10|image|DataStructure.pm:_initialize(637)|image ID argument was specified: noimage, DataStructure object will contain image information for the production imagerevision of this image 2012-08-08 15:36:54|7443|10:10|image|DataStructure.pm:_initialize(668)|retrieved data for imagerevision ID: 1 2012-08-08 15:36:54|7443|10:10|image|DataStructure.pm:_initialize(684)|retrieved data for image ID: 1 2012-08-08 15:36:55|7443|10:10|image|Module.pm:create_mn_os_object(376)|VCL::Module::OS::Linux::ManagementNode module loaded 2012-08-08 15:36:55|7443|10:10|image|Module.pm:new(196)|VCL::Module::OS::Linux::ManagementNode object created for image noimage, address: 405e5c8 2012-08-08 15:36:55|7443|10:10|image|DataStructure.pm:_automethod(836)|data structure updated, hash path: $self->request_data->{reservation}{0}{computer}{hostname}, data identifier: computer_hostname, data: |7443|10:10|image| : "localhost" 2012-08-08 15:36:55|7443|10:10|image|DataStructure.pm:_automethod(836)|data structure updated, hash path: $self->request_data->{reservation}{0}{computer}{NODENAME}, data identifier: computer_node_name, data: |7443|10:10|image| : "localhost" 2012-08-08 15:36:55|7443|10:10|image|DataStructure.pm:_automethod(836)|data structure updated, hash path: $self->request_data->{reservation}{0}{computer}{SHORTNAME}, data identifier: computer_short_name, data: |7443|10:10|image| : "localhost" 2012-08-08 15:36:55|7443|10:10|image|DataStructure.pm:_automethod(836)|data structure updated, hash path: $self->request_data->{reservation}{0}{computer}{IPaddress}, data identifier: computer_ip_address, data: |7443|10:10|image| : "127.0.0.1" 2012-08-08 15:36:55|7443|10:10|image|Module.pm:create_mn_os_object(381)|VCL::Module::OS::Linux::ManagementNode OS object created, address: 405e5c8 2012-08-08 15:36:55|7443|10:10|image|Module.pm:new(192)|VCL::image object created for state image, address: 3b0dde8 2012-08-08 15:36:55|7443|10:10|image|State.pm:initialize(88)|obtained a database handle for this state process, stored as $ENV{dbh} 2012-08-08 15:36:55|7443|10:10|image|State.pm:check_image_os(790)|no corrections need to be made to image OS: vmwarewin7 2012-08-08 15:36:55|7443|10:10|image|DataStructure.pm:is_parent_reservation(993)|returning true: parent reservation ID for this request: 10 2012-08-08 15:36:55|7443|10:10|image|utils.pm:rename_vcld_process(6785)|reservation count: 1 2012-08-08 15:36:55|7443|10:10|image|utils.pm:rename_vcld_process(6804)|PARENTIMAGE: 1 2012-08-08 15:36:55|7443|10:10|image|utils.pm:rename_vcld_process(6805)|SUBIMAGE: 0 2012-08-08 15:36:55|7443|10:10|image|utils.pm:rename_vcld_process(6823)|renamed process to 'vcld 10:10 image vclvm0001-man0>vclhv01 vmwarewin7-win7x64_base3-v0 admin' 2012-08-08 15:36:55|7443|10:10|image|DataStructure.pm:is_parent_reservation(993)|returning true: parent reservation ID for this request: 10 2012-08-08 15:36:55|7443|10:10|image|DataStructure.pm:is_parent_reservation(993)|returning true: parent reservation ID for this request: 10 2012-08-08 15:36:55|7443|10:10|image|Module.pm:create_os_object(308)|VCL::Module::OS::Windows::Version_6::7 module loaded 2012-08-08 15:36:55|7443|10:10|image|Module.pm:new(196)|VCL::Module::OS::Windows::Version_6::7 object created for image vmwarewin7-win7x64_base3-v0, address: 4061a90 2012-08-08 15:36:55|7443|10:10|image|Module.pm:create_os_object(314)|VCL::Module::OS::Windows::Version_6::7 OS object created, address: 4061a90 2012-08-08 15:36:55|7443|10:10|image|State.pm:initialize(125)|computer is a VM, attempting to create VM host OS object 2012-08-08 15:36:55|7443|10:10|image|DataStructure.pm:_initialize(613)|computer ID argument was specified, retrieving data for computer ID: 1 2012-08-08 15:36:55|7443|10:10|image|DataStructure.pm:_initialize(637)|image ID argument was specified: 1, DataStructure object will contain image information for the production imagerevision of this image 2012-08-08 15:36:55|7443|10:10|image|DataStructure.pm:_initialize(668)|retrieved data for imagerevision ID: 1 2012-08-08 15:36:55|7443|10:10|image|DataStructure.pm:_initialize(684)|retrieved data for image ID: 1 2012-08-08 15:36:55|7443|10:10|image|Module.pm:create_vmhost_os_object(454)|attempting to load VM host OS module: VCL::Module::OS::Linux::UnixLab (image: 1) 2012-08-08 15:36:55|7443|10:10|image|Module.pm:create_vmhost_os_object(460)|VM host OS module loaded: VCL::Module::OS::Linux::UnixLab 2012-08-08 15:36:55|7443|10:10|image|Module.pm:new(196)|VCL::Module::OS::Linux::UnixLab object created for image noimage, address: 407bfd8 2012-08-08 15:36:55|7443|10:10|image|Module.pm:create_vmhost_os_object(465)|VCL::Module::OS::Linux::UnixLab OS object created, address: 407bfd8 2012-08-08 15:36:55|7443|10:10|image|Module.pm:create_provisioning_object(519)|VCL::Module::Provisioning::VMware::VMware module loaded 2012-08-08 15:36:55|7443|10:10|image|Module.pm:new(200)|VCL::Module::Provisioning::VMware::VMware object created for computer vclvm0001-man0, address: 407c380 2012-08-08 15:36:55|7443|10:10|image|VMware.pm:initialize(267)|initializing VCL::Module::Provisioning::VMware::VMware object 2012-08-08 15:36:55|7443|10:10|image|DataStructure.pm:_initialize(613)|computer ID argument was specified, retrieving data for computer ID: 1 2012-08-08 15:36:55|7443|10:10|image|DataStructure.pm:_initialize(637)|image ID argument was specified: 1, DataStructure object will contain image information for the production imagerevision of this image 2012-08-08 15:36:55|7443|10:10|image|DataStructure.pm:_initialize(668)|retrieved data for imagerevision ID: 1 2012-08-08 15:36:55|7443|10:10|image|DataStructure.pm:_initialize(684)|retrieved data for image ID: 1 2012-08-08 15:36:55|7443|10:10|image|VMware.pm:get_vmhost_datastructure(1392)|created DataStructure object for VM host: vclhv01 2012-08-08 15:36:55|7443|10:10|image|VMware.pm:initialize(287)|VM profile assigned to vclhv01: VMware ESXi - double disk 2012-08-08 15:36:55|7443|10:10|image|DataStructure.pm:_initialize(613)|computer ID argument was specified, retrieving data for computer ID: 1 2012-08-08 15:36:55|7443|10:10|image|DataStructure.pm:_initialize(637)|image ID argument was specified: 1, DataStructure object will contain image information for the production imagerevision of this image 2012-08-08 15:36:55|7443|10:10|image|DataStructure.pm:_initialize(668)|retrieved data for imagerevision ID: 1 2012-08-08 15:36:55|7443|10:10|image|DataStructure.pm:_initialize(684)|retrieved data for image ID: 1 2012-08-08 15:36:55|7443|10:10|image|VMware.pm:get_vmhost_datastructure(1392)|created DataStructure object for VM host: vclhv01 2012-08-08 15:36:55|7443|10:10|image|VMware.pm:get_vmhost_api_object(1495)|attempting to load VMware control module: VCL::Module::Provisioning::VMware::vSphere_SDK 2012-08-08 15:36:55|7443|10:10|image|VMware.pm:get_vmhost_api_object(1501)|loaded VMware control module: VCL::Module::Provisioning::VMware::vSphere_SDK 2012-08-08 15:36:55|7443|10:10|image|Module.pm:new(200)|VCL::Module::Provisioning::VMware::vSphere_SDK object created for computer vclvm0001-man0, address: 4c75038 2012-08-08 15:36:55|7443|10:10|image|vSphere_SDK.pm:initialize(101)|loaded VMware vSphere SDK modules 2012-08-08 15:36:55|7443|10:10|image|vSphere_SDK.pm:initialize(145)|attempting to connect to VM host: https://vclhv01/sdk (root) 2012-08-08 15:36:55|7443|10:10|image|vSphere_SDK.pm:initialize(163)|connected to VM host: https://vclhv01/sdk, username: 'root' 2012-08-08 15:36:55|7443|10:10|image|vSphere_SDK.pm:initialize(177)|connected to vclhv01, VIM object type: Vim 2012-08-08 15:36:55|7443|10:10|image|VMware.pm:get_vmhost_api_object(1522)|created API object: VCL::Module::Provisioning::VMware::vSphere_SDK 2012-08-08 15:36:55|7443|10:10|image|vSphere_SDK.pm:is_restricted(1502)|access to the VM host via the vSphere SDK is restricted due to the license: RestrictedVersionFault 2012-08-08 15:37:19|7443|10:10|image|OS.pm:is_ssh_responding(644)|vclhv01 is NOT responding to SSH, SSH command failed, port 22: open, port 24: closed 2012-08-08 15:37:19|7443|10:10|image|VMware.pm:initialize(307)|unable to control OS of VM host vclhv01 using VCL::Module::OS::Linux::UnixLab OS object because VM host is not responding to SSH |7443|10:10|image| ---- WARNING ---- |7443|10:10|image| 2012-08-08 15:37:19|7443|10:10|image|Module.pm:create_provisioning_object(530)|provisioning object could not be created, returning 0 |7443|10:10|image| ( 0) Module.pm, create_provisioning_object (line: 530) |7443|10:10|image| (-1) State.pm, initialize (line: 136) |7443|10:10|image| (-2) Module.pm, new (line: 207) |7443|10:10|image| (-3) vcld, make_new_child (line: 567) |7443|10:10|image| (-4) vcld, main (line: 350) |7443|10:10|image| ---- WARNING ---- |7443|10:10|image| 2012-08-08 15:37:19|7443|10:10|image|State.pm:initialize(145)|failed to create provisioning object |7443|10:10|image| ( 0) State.pm, initialize (line: 145) |7443|10:10|image| (-1) Module.pm, new (line: 207) |7443|10:10|image| (-2) vcld, make_new_child (line: 567) |7443|10:10|image| (-3) vcld, main (line: 350) 2012-08-08 15:37:19|7443|10:10|image|utils.pm:delete_computerloadlog_reservation(6429)|removing computerloadlog entries matching loadstate = begin 2012-08-08 15:37:20|7443|10:10|image|utils.pm:delete_computerloadlog_reservation(6476)|deleted rows from computerloadlog for reservation id=10 2012-08-08 15:37:20|7443|10:10|image|State.pm:DESTROY(929)|VCL::image process duration: 25 seconds 2012-08-08 15:37:20|7443|10:10|image|DataStructure.pm:get_computer_private_ip_address(1630)|attempting to retrieve private IP address for computer: vclvm0001-man0 2012-08-08 15:37:20|7443|10:10|image|DataStructure.pm:get_computer_private_ip_address(1634)|retrieved contents of /etc/hosts on this management node, contains 120 lines 2012-08-08 15:37:20|7443|10:10|image|DataStructure.pm:get_computer_private_ip_address(1694)|returning IP address from /etc/hosts file: 10.128.64.100 2012-08-08 15:37:20|7443|10:10|image|utils.pm:getnewdbh(2512)|unable to use database handle stored in $ENV{dbh} 2012-08-08 15:37:20|7443|10:10|image|utils.pm:getnewdbh(2569)|database handle stored in $ENV{dbh} 2012-08-08 15:37:20|7443|10:10|image|utils.pm:is_inblockrequest(5793)|zero rows were returned from database select 2012-08-08 15:37:20|7443|10:10|image|DataStructure.pm:get_image_affiliation_name(2118)|image owner id: 1 2012-08-08 15:37:20|7443|10:10|image|DataStructure.pm:retrieve_user_data(1401)|attempting to retrieve and store data for user: user.id = '1' 2012-08-08 15:37:20|7443|10:10|image|DataStructure.pm:retrieve_user_data(1464)|data has been retrieved for user: admin (id: 1)