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