Re: Reservation Problem

Thu, 19 Mar 2009 12:47:55 -0700 

Let's analyze this log ...


2009-03-19 23:04:02|4359|137:4|new|esx.pm:load(176)|VM info command:
/usr/lib/vmware-viperl/apps/vm/vminfo.pl --server 'vclblade1' --vmname
esx3-lamp-v0_blade1 --username vcl --password 'd834jfhd734jgfhf7'



Here the esx.pm module is trying to use the vminfo.pl file (part of  
the VMware VI perl toolkit) to ask the hypervisor (vclblade1) about  
the VM 'esx3-lamp-v0_blade1'  Clearly this isn't working because the  
next line in the log is:



2009-03-19 23:04:04|4359|137:4|new|esx.pm:load(179)|VM info output:
Virtual Machine esx3-lamp-v0_blade1 not found.




So why is the command failing?  The log says it's because esx3- 
lamp_v0_blade1 does not exist.  Is there a DNS entry for that blade  
that would allow esx3-lamp_v0_blade1 to resolve to IP address of the  
hypervisor?



Also, we output the commands the esx.pm module runs to the log so that  
they can be run manually.  Which means you can test this command  
without needing to test all of VCL by running the following on the  
command line:



/usr/lib/vmware-viperl/apps/vm/vminfo.pl --server 'vclblade1' --vmname  
esx3-lamp-v0_blade1 --username vcl --password 'd834jfhd734jgfhf7'


Best,
Brian

Brian Bouterse
Secure Open Systems Initiative
919.698.8796




On Mar 19, 2009, at 3:20 PM, Melba Lopez wrote:


I've verified and tried everything you have mentioned.  I also  
followed the
steps in "esx.README" to make sure I configured everything ok, but I  
still

get a failure. Good news is that the reservation doesn't stay stuck in
"Pending" and actually returns as "Failed".  I also do not see it

complaining about the host name, but rather that it cannot "load"  
the VM.



Do you have any other suggestions on what other configurations I'm  
missing?


*Log of Reservation:*



*2009-03-19 23:04:02|4359|137:4|new|esx.pm:load(166)|Entered ESX  
module,
loading esx3-lamp-v0 on esx3-lamp-v0_blade1 (on vclblade1) for  
reservation 4

2009-03-19 23:04:02|4359|137:4|new|esx.pm:load(176)|VM info command:

/usr/lib/vmware-viperl/apps/vm/vminfo.pl --server 'vclblade1' -- 
vmname

esx3-lamp-v0_blade1 --username vcl --password 'd834jfhd734jgfhf7'

2009-03-19 23:04:04|4359|137:4|new|vcld:REAPER(770)|setting $? to  
0, exit

status: 0
2009-03-19 23:04:04|4359|137:4|new|esx.pm:load(179)|VM info output:
Virtual Machine esx3-lamp-v0_blade1 not found.

2009-03-19 23:04:04|4359|137:4|new|vcld:REAPER(770)|setting $? to  
0, exit

status: 0

2009-03-19 23:04:04|4359|137:4|new|esx.pm:load(212)|Output from  
remove

command is:
2009-03-19 23:04:04|4359|137:4|new|esx.pm:load(227)|COPIED VMDK
SUCCESSFULLY
2009-03-19 23:04:04|4359|137:4|new|esx.pm:load(235)|SSHing to copy
vmdk-flat file
2009-03-19 23:04:14|2420|vcld:main(166)|lastcheckin time updated for
management node 1: 2009-03-19 23:04:14
2009-03-19 23:04:26|2420|vcld:main(166)|lastcheckin time updated for
management node 1: 2009-03-19 23:04:26

2009-03-19 23:04:28|4359|137:4|new|vcld:REAPER(770)|setting $? to  
0, exit

status: 0

2009-03-19 23:04:28|4359|137:4|new|vcld:REAPER(751)|process reaped:  
pid:

4374, $?: 0, exit status: 0

2009-03-19 23:04:28|4359|137:4|new|vcld:REAPER(770)|setting $? to  
0, exit

status: 0
2009-03-19 23:04:28|4359|137:4|new|esx.pm:load(258)|adapter= lsilogic
2009-03-19 23:04:28|4359|137:4|new|esx.pm:load(300)|wrote vmxarray to
/mnt/vcl/inuse/esx3-lamp-v0_blade1/esx3-lamp-v0.vmx

2009-03-19 23:04:29|4359|137:4|new|vcld:REAPER(770)|setting $? to  
0, exit

status: 0
2009-03-19 23:04:29|4359|137:4|new|esx.pm:load(321)|Registered:
|4359|137:4|new| No host found with name vclblade1.
2009-03-19 23:04:29|4359|137:4|new|esx.pm:load(330)|Power on command:

/usr/lib/vmware-viperl/apps/vm/vmcontrol.pl --server 'vclblade1' -- 
vmname

esx3-lamp-v0_blade1 --operation poweron --username vcl --password
'd834jfhd734jgfhf7'

2009-03-19 23:04:31|4359|137:4|new|vcld:REAPER(770)|setting $? to  
0, exit

status: 0

2009-03-19 23:04:31|4359|137:4|new|esx.pm:load(333)|Powered on:  
Virtual

Machine esx3-lamp-v0_blade1 not found.

2009-03-19 23:04:32|4359|137:4|new|vcld:REAPER(770)|setting $? to  
0, exit

status: 0

2009-03-19 23:04:32|4359|137:4|new|vcld:REAPER(770)|setting $? to  
0, exit

status: 0

2009-03-19 23:04:32|4359|137:4|new|utils.pm:mail(1281)|SUCCESS --  
Sending

mail To: r...@localhost, PROBLEM -- esx.pm

|4359|137:4|new| ---- CRITICAL ----

|4359|137:4|new| 2009-03-19 23:04:32|4359|137:4|new| 
esx.pm:load(341)|Could

not query for VM in VI PERL API
|4359|137:4|new| ( 0) utils.pm, notify (line: 683)
|4359|137:4|new| (-1) esx.pm, load (line: 341)
|4359|137:4|new| (-2) new.pm, reload_image (line: 664)
|4359|137:4|new| (-3) new.pm, process (line: 266)
|4359|137:4|new| (-4) vcld, make_new_child (line: 606)
|4359|137:4|new| (-5) vcld, main (line: 353)


|4359|137:4|new| ---- WARNING ----

|4359|137:4|new| 2009-03-19 23:04:32|4359|137:4|new| 
new.pm:reload_image(669)|esx3-lamp-v0

failed to load on esx3-lamp-v0_blade1, returning
|4359|137:4|new| ( 0) utils.pm, notify (line: 683)
|4359|137:4|new| (-1) new.pm, reload_image (line: 669)
|4359|137:4|new| (-2) new.pm, process (line: 266)
|4359|137:4|new| (-3) vcld, make_new_child (line: 606)
|4359|137:4|new| (-4) vcld, main (line: 353)


2009-03-19 23:04:32|4359|137:4|new|utils.pm:insertloadlog(5300)| 
inserted

computer=11, loadimagefailed, esx3-lamp-v0 failed to load on
esx3-lamp-v0_blade1

|4359|137:4|new| ---- WARNING ----

|4359|137:4|new| 2009-03-19 23:04:32|4359|137:4|new| 
new.pm:process(313)|failed

to load esx3-lamp-v0_blade1 with esx3-lamp-v0
|4359|137:4|new| ( 0) utils.pm, notify (line: 683)
|4359|137:4|new| (-1) new.pm, process (line: 313)
|4359|137:4|new| (-2) vcld, make_new_child (line: 606)
|4359|137:4|new| (-3) vcld, main (line: 353)


2009-03-19 23:04:32|4359|137:4|new|vcld:REAPER(770)|setting $? to  
0, exit

status: 0

2009-03-19 23:04:32|4359|137:4|new|vcld:REAPER(770)|setting $? to  
0, exit

status: 0

2009-03-19 23:04:32|4359|137:4|new|utils.pm:mail(1281)|SUCCESS --  
Sending

mail To: r...@localhost, PROBLEM -- State.pm

|4359|137:4|new| ---- CRITICAL ----
|4359|137:4|new| 2009-03-19

23:04:32|4359|137:4|new|State.pm:reservation_failed(285)| 
reservation failed

on esx3-lamp-v0_blade1: process failed after trying to load or make
available
|4359|137:4|new| ( 0) utils.pm, notify (line: 683)
|4359|137:4|new| (-1) State.pm, reservation_failed (line: 285)
|4359|137:4|new| (-2) new.pm, process (line: 316)
|4359|137:4|new| (-3) vcld, make_new_child (line: 606)
|4359|137:4|new| (-4) vcld, main (line: 353)


2009-03-19 23:04:32|4359|137:4|new|utils.pm:insertloadlog(5300)| 
inserted
computer=11, failed, process failed after trying to load or make  
available

2009-03-19
23:04:32|4359|137:4|new|State.pm:reservation_failed(288)|inserted
computerloadlog entry

2009-03-19 23:04:32|4359|137:4|new|State.pm:reservation_failed(296)| 
updated

log ending value to 'failed', logid=71

2009-03-19 23:04:32|4359|137:4|new| 
utils.pm:update_computer_state(2305)|computer

11 state updated to: failed
2009-03-19
23:04:32|4359|137:4|new|State.pm:reservation_failed(304)|computer
esx3-lamp-v0_blade1 (11) state set to failed

2009-03-19 23:04:32|4359|137:4|new| 
utils.pm:update_request_state(2263)|request

137 state updated to: failed, laststate to: new

2009-03-19 23:04:32|4359|137:4|new|State.pm:reservation_failed(312)| 
set

request state to 'failed'/'new'

2009-03-19 23:04:32|4359|137:4|new|utils.pm:is_inblockrequest(7356)| 
zero

rows were returned from database select
2009-03-19

23:04:32|4359|137:4|new|State.pm:reservation_failed(330)|esx3-lamp- 
v0_blade1

is NOT in blockcomputers table

2009-03-19 23:04:32|4359|137:4|new|State.pm:reservation_failed(333)| 
exiting

1

2009-03-19 23:04:32|4359|137:4|new|State.pm:DESTROY(435)|destructor  
called,

ref($self)=VCL::new

2009-03-19 23:04:32|4359|137:4|new| 
utils.pm:delete_computerloadlog_reservation(8013)|removing

computerloadlog entries matching loadstate = begin

2009-03-19 23:04:32|4359|137:4|new| 
utils.pm:delete_computerloadlog_reservation(8060)|deleted

rows from computerloadlog for reservation id=4
2009-03-19 23:04:32|4359|137:4|new|State.pm:DESTROY(438)|removed
computerloadlog rows with loadstate=begin for reservation

2009-03-19 23:04:32|4359|137:4|new|State.pm:DESTROY(446)|number of  
database

handles state process created: 1

2009-03-19 23:04:32|4359|137:4|new|State.pm:DESTROY(455)|process  
has a

database handle stored in $ENV{dbh}, attempting disconnect
2009-03-19 23:04:32|4359|137:4|new|State.pm:DESTROY(457)|$ENV{dbh}:
database disconnect successful

2009-03-19 23:04:32|2420|vcld:REAPER(751)|process reaped: pid:  
4359, $?:

256, exit status: 1
2009-03-19 23:04:32|2420|vcld:REAPER(756)|VCL process exited for
reservation 4

2009-03-19 23:04:32|2420|vcld:REAPER(770)|setting $? to 256, exit  
status: 1

*






On Thu, Mar 19, 2009 at 9:22 AM, Brian Bouterse <bmbou...@ncsu.edu>  
wrote:



Your installation does correctly call the esx.pm module because I  
can see
the code inside of it executing through your log post.  The problem  
seems to

be that the vmhost_ variables are not being passed into the module.


This could be because the associations are not all correct in the  
database.
I'll give an example of a correct association below where I only  
include

the important information:

In the vmtype table ensure you have an entry:
<id,name=vmwareESX3>

In the vmprofile table have an entry for your hypervisor:
<id,vmtype=the entry from the vmtype table,datastorepath=NFS mount

point(ip:/path/to/ 
NFS),virtualswitch0=Management,virtualswitch1=Public,username=user

on hypervisor,password=password of hypervisor user>

In the computer table you should have:
an entry for a hypervisor:
<id,hostname,IPaddress,type=blade,vmhostid=NULL,vmtypeid=NULL>
an entry for a virtual machine slot:

<id,hostname,type=virtualmachine,vmhost=id of  
hypervisor,vmtype=entry from

vmtype table>


The vmhost table associates the hypervisor's entry in the computer  
table
with the hypervisor type declared in vmprofile.  In the vmhost  
table you

will require:

<computerid=id of hypervisor,vmprofileid=id of hypervisor in  
vmprofile>



Here is a dump example from a working database:

INSERT INTO `vmtype` (`id`, `name`) VALUES (5, 'vmwareESX3');

INSERT INTO `vmprofile` (`id`, `profilename`, `vmtypeid`, `imageid`,

`nasshare`, `datastorepath`, `vmpath`, `virtualswitch0`,  
`virtualswitch1`,
`vmdisk`, `username`, `password`) VALUES (4, 'VMware ESX SAN ', 2,  
4, NULL,

'152.14.17.112:/mnt/export', '/vmfs/volumes/storage1', 'Management',
'Public', 'networkdisk', 'vcl', 'j45789fgdkhj542j');


INSERT INTO `computer` (`id`, `stateid`, `ownerid`, `deptid`,  
`platformid`,

`scheduleid`, `currentimageid`, `preferredimageid`, `nextimageid`,

`imagerevisionid`, `RAM`, `procnumber`, `procspeed`, `network`,  
`hostname`,
`IPaddress`, `privateIPaddress`, `eth0macaddress`,  
`eth1macaddress`, `type`,
`provisioningid`, `drivetype`, `deleted`, `notes`, `lastcheck`,  
`location`,
`dsa`, `dsapub`, `rsa`, `rsapub`, `host`, `hostpub`, `vmhostid`,  
`vmtypeid`)
VALUES (2, 2, 1, 1, 1, 1, 10, 10, 10, 10, 1024, 1, 1000, 1000,  
'test_vm',

'152.14.17.18', '10.0.5.1', '00:50:56:01:4d:9b', '00:50:56:01:4d:9c',

'virtualmachine', 4, 'hda', 0, '', NULL, NULL, NULL, NULL, NULL,  
NULL, NULL,

NULL, 1, 5), (3, 2, 1, 1, 1, 1, 4, 4, 0, 0, 512, 1, 500, 10, '

blade2-1.cnl.ncsu.edu', '152.14.17.235', NULL, NULL, NULL, 'blade',  
1,
'hda', 0, '', NULL, NULL, NULL, NULL, NULL, NULL, NULL, NULL, NULL,  
NULL);


INSERT INTO `vmhost` (`id`, `computerid`, `vmlimit`, `vmprofileid`,
`vmkernalnic`, `vmwaredisk`) VALUES (1, 3, 3, 4, NULL, 'localdisk');


Best,
Brian


Brian Bouterse
Secure Open Systems Initiative
919.698.8796





On Mar 18, 2009, at 11:55 PM, Melba Lopez wrote:


I'm trying to setup VCL to work in our environment, but we can't  
seem to

get
it quite working.

When we schedule a reservation, it goes through and shows that it's

"Pending".  However, it stays in that mode and won't ever come  
out.  We

don't get any notification of accepting or rejecting etc.


Looking through the log file, the following message seems to be  
repeating.

What configuration am I missing?

"|30189|116:16|new| ---- WARNING ----



|30189|116:16|new| 2009-03-18



22:28:17|30189|116:16|new|vcld:warning_handler(648)|Use of  
uninitialized

value $vmhost_hostname in concatenation (.) or string at
/opt/vcl/bin/../lib/VCL/Module/Provisioning/esx.pm line 325.

|30189|116:16|new| ( 0) utils.pm, notify (line: 683)




|30189|116:16|new| (-1) vcld, warning_handler (line: 648)




|30189|116:16|new| (-2) esx.pm, load (line: 325)




|30189|116:16|new| (-3) new.pm, reload_image (line: 664)




|30189|116:16|new| (-4) new.pm, process (line: 266)




|30189|116:16|new| (-5) vcld, make_new_child (line: 606)




|30189|116:16|new| (-6) vcld, main (line: 353)






2009-03-18 22:28:17|30189|116:16|new|esx.pm:load(330)|Power on  
command:

/usr/lib/vmware-viperl/apps/vm/vmcontrol.pl --server '' --vmname
vclblade1
--operation poweron --username vcl --password 'd834jfhd734jgfhf7'


Error: Server version unavailable at 'https:///sdk/ 
vimService.wsdl' :1:



parser error : Start tag expected, '<' not found

500 No Host option provided





^ at /usr/local/lib/perl5/site_perl/5.10.0/VMware/VICommon.pm  
line 323








2009-03-18 22:28:17|30189|116:16|new|vcld:REAPER(770)|setting $?  
to 512,

exit status: 2

2009-03-18 22:28:17|30189|116:16|new|esx.pm:load(333)|Powered on:"































					Reply via email to