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