Andy  

$ssh_options doesn't have vcl.key. (ie. -i /path/to/vcl.key)  
I've changed the code to test it - added:

$ssh_options = $ssh_options." -i /etc/vcl/vcl.key";

right before $ssh object is created and it seemed to communicated with host OK 
this time:

...
2012-05-01 22:38:16|1097|435:427|reload|OS.pm:(eval)(1946)|created 
Net::SSH::Expect object to control VMHOST1
2012-05-01 22:38:16|1097|435:427|reload|OS.pm:(eval)(1947)|ssh_options: -o 
StrictHostKeyChecking=no -i /etc/vcl/vcl.key (<-- before the change $ssh_option 
was just '-o StrictHostKeyChecking=no')


2012-05-01 22:38:19|1097|435:427|reload|VIM_SSH.pm:initialize(138)|VIM 
executable available on VM host: vim-cmd
2012-05-01 
22:38:19|1097|435:427|reload|VIM_SSH.pm:initialize(140)|VCL::Module::Provisioning::VMware::VIM_SSH
 object initialized
2012-05-01 
22:38:19|1097|435:427|reload|VMware.pm:get_vmhost_api_object(1522)|created API 
object: VCL::Module::Provisioning::VMware::VIM_SSH
2012-05-01 22:38:19|1097|435:427|reload|VMware.pm:initialize(312)|VM host 
VMHOST1 will be controlled using vim-cmd via SSH
2012-05-01 22:38:19|1097|435:427|reload|VMware.pm:initialize(327)|VMware OS and 
API objects created for VM host VMHOST1:
|1097|435:427|reload| VM host OS object type: VCL::Module::OS::Linux
|1097|435:427|reload| VMware API object type: 
VCL::Module::Provisioning::VMware::VIM_SSH
2012-05-01 
22:38:19|1097|435:427|reload|VMware.pm:get_vmhost_product_name(6514)|VMware 
product being used on VM host VMHOST1: 'VMware ESXi 5.0.0 build-469512'
2012-05-01 22:38:19|1097|435:427|reload|VIM_SSH.pm:_run_vim_cmd(193)|vim-cmd 
call count: 1 (hostsvc/datastore/listsummary)
2012-05-01 22:38:19|1097|435:427|reload|VIM_SSH.pm:_run_vim_cmd(208)|executed 
command on VM host VMHOST1: vim-cmd hostsvc/datastore/listsummary


…

I've double checked the setting for vcl.key under management node and it's 
present.  

Thank you.

--
Dmitri Chebotarov
Virtual Computing Lab Systems Engineer, TSD - Ent Servers & Messaging
223 Aquia Building, Ffx, MSN: 1B5
Phone: (703) 993-6175
Fax: (703) 993-3404


On Tuesday, May 1, 2012 at 21:47 , Dmitri Chebotarov wrote:

> Andy,  
>  
> Here is the full log.
>  
> Thank you.
>  
>  
>  
> VCL::new object could not be created and initialized
> ------------------------------------------------------------------------
> time: 2012-05-01 16:54:28
> caller: vcld:make_new_child(575)
> ( 0) vcld, make_new_child (line: 575)
> (-1) vcld, main (line: 350)
> ------------------------------------------------------------------------
> management node: sand-vcl23
> reservation PID: 16065
> parent vcld PID: 15907
> request ID: 433
> reservation ID: 425
> request state/laststate: reload/reload
> request start time: 2012-05-01 16:45:00
> request end time: 2012-05-01 17:05:00
> for imaging: no
> log ID: none
> computer: sandbox-vcl-4
> computer id: 46
> computer type: virtualmachine
> computer eth0 MAC address: 00:50:56:00:10:08
> computer eth1 MAC address: 00:50:56:00:10:09
> computer private IP address: private-.5.14
> computer public IP address: public-.244
> computer in block allocation: no
> provisioning module: VCL::Module::Provisioning::VMware::VMware
> vm host: VMHOST1
> vm host ID: 5
> vm host computer ID: 85
> vm profile: VMware ESXi - local & network storage
> vm profile VM path: /vmfs/volumes/local-datastore/runningImages
> vm profile repository path: <undefined>
> vm profile datastore path: /vmfs/volumes/sandbox-Image-Library/baseImages
> vm profile disk type: networkdisk
> image: vmwarelinux-CentOSxCat69-v0
> image display name: CentOS 5.5 (persistent)
> image ID: 69
> image revision ID: 72
> image size: 8192 MB
> use Sysprep: no
> root access: yes
> image owner ID: 1
> image owner affiliation: Local
> image revision date created: 2012-02-09 15:11:37
> image revision production: yes
> OS module: VCL::Module::OS::Linux
> user: vclreload
> user name: vcl reload
> user ID: 2
> user affiliation: Local
> ------------------------------------------------------------------------
> RECENT LOG ENTRIES FOR THIS PROCESS:
> 2012-05-01 
> 16:54:21|16065|433:425|reload|VMware.pm:initialize(267)|initializing 
> VCL::Module::Provisioning::VMware::VMware object
> 2012-05-01 
> 16:54:21|16065|433:425|reload|DataStructure.pm:_initialize(616)|computer ID 
> argument was specified, retrieving data for computer ID: 85
> 2012-05-01 
> 16:54:21|16065|433:425|reload|DataStructure.pm:_initialize(640)|image ID 
> argument was specified: 56, DataStructure object will contain image 
> information for the production imagerevision of this image
> 2012-05-01 
> 16:54:21|16065|433:425|reload|DataStructure.pm:_initialize(671)|retrieved 
> data for imagerevision ID: 71
> 2012-05-01 
> 16:54:21|16065|433:425|reload|DataStructure.pm:_initialize(687)|retrieved 
> data for image ID: 56
> 2012-05-01 
> 16:54:21|16065|433:425|reload|VMware.pm:get_vmhost_datastructure(1392)|created
>  DataStructure object for VM host: VMHOST1
> 2012-05-01 16:54:21|16065|433:425|reload|VMware.pm:initialize(287)|VM profile 
> assigned to VMHOST1: VMware ESXi - local & network storage
> 2012-05-01 
> 16:54:21|16065|433:425|reload|DataStructure.pm:_initialize(616)|computer ID 
> argument was specified, retrieving data for computer ID: 85
> 2012-05-01 
> 16:54:21|16065|433:425|reload|DataStructure.pm:_initialize(640)|image ID 
> argument was specified: 56, DataStructure object will contain image 
> information for the production imagerevision of this image
> 2012-05-01 
> 16:54:21|16065|433:425|reload|DataStructure.pm:_initialize(671)|retrieved 
> data for imagerevision ID: 71
> 2012-05-01 
> 16:54:21|16065|433:425|reload|DataStructure.pm:_initialize(687)|retrieved 
> data for image ID: 56
> 2012-05-01 
> 16:54:21|16065|433:425|reload|VMware.pm:get_vmhost_datastructure(1392)|created
>  DataStructure object for VM host: VMHOST1
> 2012-05-01 
> 16:54:21|16065|433:425|reload|VMware.pm:get_vmhost_api_object(1495)|attempting
>  to load VMware control module: VCL::Module::Provisioning::VMware::vSphere_SDK
> 2012-05-01 
> 16:54:21|16065|433:425|reload|VMware.pm:get_vmhost_api_object(1501)|loaded 
> VMware control module: VCL::Module::Provisioning::VMware::vSphere_SDK
> 2012-05-01 
> 16:54:21|16065|433:425|reload|Module.pm:new(200)|VCL::Module::Provisioning::VMware::vSphere_SDK
>  object created for computer sandbox-vcl-4, address: 197b9e60
> 2012-05-01 
> 16:54:21|16065|433:425|reload|vSphere_SDK.pm:initialize(93)|vSphere SDK for 
> Perl does not appear to be installed on this managment node, unable to load 
> VMware vSphere SDK Perl modules
> 2012-05-01 
> 16:54:21|16065|433:425|reload|VMware.pm:get_vmhost_api_object(1515)|API 
> object could not be created: VCL::Module::Provisioning::VMware::vSphere_SDK
> 2012-05-01 16:54:21|16065|433:425|reload|utils.pm:(eval)(5213)|waiting up to 
> 30 seconds for SSH process to finish
> 2012-05-01 16:54:22|16065|433:425|reload|OS.pm:is_ssh_responding(631)|VMHOST1 
> is responding to SSH, port 22: open, port 24: closed
> 2012-05-01 16:54:22|16065|433:425|reload|VMware.pm:initialize(303)|OS on VM 
> host VMHOST1 will be controlled using VCL::Module::OS::Linux OS object
> 2012-05-01 
> 16:54:22|16065|433:425|reload|DataStructure.pm:_initialize(616)|computer ID 
> argument was specified, retrieving data for computer ID: 85
> 2012-05-01 
> 16:54:22|16065|433:425|reload|DataStructure.pm:_initialize(640)|image ID 
> argument was specified: 56, DataStructure object will contain image 
> information for the production imagerevision of this image
> 2012-05-01 
> 16:54:22|16065|433:425|reload|DataStructure.pm:_initialize(671)|retrieved 
> data for imagerevision ID: 71
> 2012-05-01 
> 16:54:22|16065|433:425|reload|DataStructure.pm:_initialize(687)|retrieved 
> data for image ID: 56
> 2012-05-01 
> 16:54:22|16065|433:425|reload|VMware.pm:get_vmhost_datastructure(1392)|created
>  DataStructure object for VM host: VMHOST1
> 2012-05-01 
> 16:54:22|16065|433:425|reload|VMware.pm:get_vmhost_api_object(1495)|attempting
>  to load VMware control module: VCL::Module::Provisioning::VMware::VIM_SSH
> 2012-05-01 
> 16:54:22|16065|433:425|reload|VMware.pm:get_vmhost_api_object(1501)|loaded 
> VMware control module: VCL::Module::Provisioning::VMware::VIM_SSH
> 2012-05-01 
> 16:54:22|16065|433:425|reload|Module.pm:new(200)|VCL::Module::Provisioning::VMware::VIM_SSH
>  object created for computer sandbox-vcl-4, address: 197b9e70
> 2012-05-01 16:54:22|16065|433:425|reload|OS.pm:(eval)(1944)|created 
> Net::SSH::Expect object to control VMHOST1
> |16065|433:425|reload| ---- WARNING ----
> |16065|433:425|reload| 2012-05-01 
> 16:54:25|16065|433:425|reload|OS.pm:(eval)(1973)|unable to connect to 
> VMHOST1, SSH is requesting a password but password authentication is not 
> implemented, password is not configured, output:
> |16065|433:425|reload| Password:
> |16065|433:425|reload| ( 0) OS.pm, (eval) (line: 1973)
> |16065|433:425|reload| (-1) OS.pm, execute_new (line: 1933)
> |16065|433:425|reload| (-2) OS.pm, execute (line: 1804)
> |16065|433:425|reload| (-3) VIM_SSH.pm, initialize (line: 119)
> |16065|433:425|reload| (-4) Module.pm, new (line: 207)
> |16065|433:425|reload| (-5) VMware.pm, (eval) (line: 1505)
> 2012-05-01 16:54:25|16065|433:425|reload|VIM_SSH.pm:initialize(121)|VIM 
> executable is not available on the VM host
> 2012-05-01 
> 16:54:25|16065|433:425|reload|VMware.pm:get_vmhost_api_object(1515)|API 
> object could not be created: VCL::Module::Provisioning::VMware::VIM_SSH
> 2012-05-01 
> 16:54:25|16065|433:425|reload|DataStructure.pm:_initialize(616)|computer ID 
> argument was specified, retrieving data for computer ID: 85
> 2012-05-01 
> 16:54:25|16065|433:425|reload|DataStructure.pm:_initialize(640)|image ID 
> argument was specified: 56, DataStructure object will contain image 
> information for the production imagerevision of this image
> 2012-05-01 
> 16:54:25|16065|433:425|reload|DataStructure.pm:_initialize(671)|retrieved 
> data for imagerevision ID: 71
> 2012-05-01 
> 16:54:25|16065|433:425|reload|DataStructure.pm:_initialize(687)|retrieved 
> data for image ID: 56
> 2012-05-01 
> 16:54:25|16065|433:425|reload|VMware.pm:get_vmhost_datastructure(1392)|created
>  DataStructure object for VM host: VMHOST1
> 2012-05-01 
> 16:54:25|16065|433:425|reload|VMware.pm:get_vmhost_api_object(1495)|attempting
>  to load VMware control module: VCL::Module::Provisioning::VMware::vmware_cmd
> 2012-05-01 
> 16:54:25|16065|433:425|reload|VMware.pm:get_vmhost_api_object(1501)|loaded 
> VMware control module: VCL::Module::Provisioning::VMware::vmware_cmd
> 2012-05-01 
> 16:54:25|16065|433:425|reload|Module.pm:new(200)|VCL::Module::Provisioning::VMware::vmware_cmd
>  object created for computer sandbox-vcl-4, address: 19882d70
> 2012-05-01 16:54:25|16065|433:425|reload|OS.pm:(eval)(1944)|created 
> Net::SSH::Expect object to control VMHOST1
> |16065|433:425|reload| ---- WARNING ----
> |16065|433:425|reload| 2012-05-01 
> 16:54:28|16065|433:425|reload|OS.pm:(eval)(1973)|unable to connect to 
> VMHOST1, SSH is requesting a password but password authentication is not 
> implemented, password is not configured, output:
> |16065|433:425|reload| Password:
> |16065|433:425|reload| ( 0) OS.pm, (eval) (line: 1973)
> |16065|433:425|reload| (-1) OS.pm, execute_new (line: 1933)
> |16065|433:425|reload| (-2) OS.pm, execute (line: 1804)
> |16065|433:425|reload| (-3) vmware_cmd.pm, initialize (line: 101)
> |16065|433:425|reload| (-4) Module.pm, new (line: 207)
> |16065|433:425|reload| (-5) VMware.pm, (eval) (line: 1505)
> |16065|433:425|reload| ---- WARNING ----
> |16065|433:425|reload| 2012-05-01 
> 16:54:28|16065|433:425|reload|vmware_cmd.pm:initialize(103)|failed to run SSH 
> command to determine if vmware-cmd is available on the VM host
> |16065|433:425|reload| ( 0) vmware_cmd.pm, initialize (line: 103)
> |16065|433:425|reload| (-1) Module.pm, new (line: 207)
> |16065|433:425|reload| (-2) VMware.pm, (eval) (line: 1505)
> |16065|433:425|reload| (-3) VMware.pm, get_vmhost_api_object (line: 1505)
> |16065|433:425|reload| (-4) VMware.pm, initialize (line: 312)
> |16065|433:425|reload| (-5) Module.pm, new (line: 207)
> 2012-05-01 
> 16:54:28|16065|433:425|reload|VMware.pm:get_vmhost_api_object(1515)|API 
> object could not be created: VCL::Module::Provisioning::VMware::vmware_cmd
> |16065|433:425|reload| ---- WARNING ----
> |16065|433:425|reload| 2012-05-01 
> 16:54:28|16065|433:425|reload|VMware.pm:initialize(319)|failed to create an 
> object to control VM host: VMHOST1
> |16065|433:425|reload| ( 0) VMware.pm, initialize (line: 319)
> |16065|433:425|reload| (-1) Module.pm, new (line: 207)
> |16065|433:425|reload| (-2) Module.pm, create_provisioning_object (line: 521)
> |16065|433:425|reload| (-3) State.pm, initialize (line: 136)
> |16065|433:425|reload| (-4) Module.pm, new (line: 207)
> |16065|433:425|reload| (-5) vcld, make_new_child (line: 568)
> |16065|433:425|reload| ---- WARNING ----
> |16065|433:425|reload| 2012-05-01 
> 16:54:28|16065|433:425|reload|Module.pm:create_provisioning_object(529)|provisioning
>  object could not be created, returning 0
> |16065|433:425|reload| ( 0) Module.pm, create_provisioning_object (line: 529)
> |16065|433:425|reload| (-1) State.pm, initialize (line: 136)
> |16065|433:425|reload| (-2) Module.pm, new (line: 207)
> |16065|433:425|reload| (-3) vcld, make_new_child (line: 568)
> |16065|433:425|reload| (-4) vcld, main (line: 350)
> |16065|433:425|reload| ---- WARNING ----
> |16065|433:425|reload| 2012-05-01 
> 16:54:28|16065|433:425|reload|State.pm:initialize(145)|failed to create 
> provisioning object
> |16065|433:425|reload| ( 0) State.pm, initialize (line: 145)
> |16065|433:425|reload| (-1) Module.pm, new (line: 207)
> |16065|433:425|reload| (-2) vcld, make_new_child (line: 568)
> |16065|433:425|reload| (-3) vcld, main (line: 350)
> 2012-05-01 
> 16:54:28|16065|433:425|reload|utils.pm:delete_computerloadlog_reservation(6692)|removing
>  computerloadlog entries matching loadstate = begin
> 2012-05-01 
> 16:54:28|16065|433:425|reload|utils.pm:delete_computerloadlog_reservation(6739)|deleted
>  rows from computerloadlog for reservation id=425
> 2012-05-01 16:54:28|16065|433:425|reload|State.pm:DESTROY(929)|VCL::new 
> process duration: 7 seconds
> 2012-05-01 
> 16:54:28|16065|433:425|reload|DataStructure.pm:get_computer_private_ip_address(1633)|attempting
>  to retrieve private IP address for computer: sandbox-vcl-4
> 2012-05-01 
> 16:54:28|16065|433:425|reload|DataStructure.pm:get_computer_private_ip_address(1637)|retrieved
>  contents of /etc/hosts on this management node, contains 41 lines
> 2012-05-01 
> 16:54:28|16065|433:425|reload|DataStructure.pm:get_computer_private_ip_address(1697)|returning
>  IP address from /etc/hosts file: private-.5.14
> 2012-05-01 16:54:28|16065|433:425|reload|utils.pm:getnewdbh(2754)|unable to 
> use database handle stored in $ENV{dbh}
> 2012-05-01 16:54:28|16065|433:425|reload|utils.pm:getnewdbh(2811)|database 
> handle stored in $ENV{dbh}
> 2012-05-01 
> 16:54:28|16065|433:425|reload|utils.pm:is_inblockrequest(6056)|zero rows were 
> returned from database select
> 2012-05-01 
> 16:54:28|16065|433:425|reload|DataStructure.pm:get_image_affiliation_name(2121)|image
>  owner id: 1
> 2012-05-01 
> 16:54:28|16065|433:425|reload|DataStructure.pm:retrieve_user_data(1404)|attempting
>  to retrieve and store data for user: user.id = '1'
> 2012-05-01 
> 16:54:28|16065|433:425|reload|DataStructure.pm:retrieve_user_data(1467)|data 
> has been retrieved for user: admin (id: 1)
>  
>  
>  
> --
> Dmitri Chebotarov
> Virtual Computing Lab Systems Engineer, TSD - Ent Servers & Messaging
> 223 Aquia Building, Ffx, MSN: 1B5
> Phone: (703) 993-6175
> Fax: (703) 993-3404
>  
>  
> On Tuesday, May 1, 2012 at 17:07 , Andy Kurth wrote:
>  
> > Please send all of the vcld.log output for a failed reservation.
> > -Andy
> >  
> > On Tue, May 1, 2012 at 4:46 PM, Dmitri Chebotarov <dcheb...@gmu.edu 
> > (mailto:dcheb...@gmu.edu)> wrote:
> > > Hi
> > >  
> > > I've upgraded from 2.2.1 to 2.3.
> > > Web and management node seems to be working OK - vcld communicated with 
> > > the
> > > database and front-end displays right information.
> > >  
> > > For some reason after the upgrade I cannot communicate with any of 
> > > vmhosts.
> > > It seems like VCL ignoring vcl.key and try to login with 
> > > username/password:
> > >  
> > > ...
> > > |14100|427:419|reload| 2012-05-01
> > > 16:22:04|14100|427:419|reload|OS.pm:(eval)(1974)|unable to connect to
> > > VMHOST-1, SSH is requesting a password but password authentication is not
> > > implemented, password is not configured, output:
> > > |14100|427:419|reload| Password:
> > > …
> > >  
> > > Is it normal and I need to configure username/password, or am I missing
> > > something in VCL 2.3?
> > >  
> > > Thank you.
> > >  
> > >  
> > > --
> > > Dmitri Chebotarov
> > > Virtual Computing Lab Systems Engineer, TSD - Ent Servers & Messaging
> > > 223 Aquia Building, Ffx, MSN: 1B5
> > > Phone: (703) 993-6175
> > > Fax: (703) 993-3404
> >  
>  



Reply via email to