Re: VCL image capture dies, "failed to prepare vmx file"

Mon, 25 Jun 2012 06:13:16 -0700 

hi all,
new to this list. i have started setting up vcl here and clemson university and this thread has touched on one of the questions i had in trying to do so. do i assign mac addresses based on what esxi generates? if not, how do i map those correctly? thanks. 

will


On 06/20/2012 10:16 AM, Josh Thompson wrote:

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Michael,

Unfortunately, yes, in 2.2.1, you can only set MAC addresses via the add
multiple computers page.  You'll need to set them in the database.  This is
fixed in 2.3.

Josh

On Wednesday, June 20, 2012 9:12:52 AM Michael Jinks wrote:

Thanks Aaron.

Ah, yes.  It didn't occur to me that we'd have to have MAC addresses
defined for a machine we're capturing *from*.  I figured, well, it's
running and has IP addresses...

At any rate, I'm looking around the UI and I can't find any page that
will let me enter a MAC address for an existing computer record.  Is
this something I have to do by hand in the database?

On Wed, Jun 20, 2012 at 08:46:40AM -0400, Aaron Peeler wrote:

Hello Michael,

One thing that stands out in the log is that your MAC addresses are not
defined. computer eth0 MAC address: <undefined>
computer eth1 MAC address: <undefined>

This will be needed to correctly create the vmx file and thus get an
address from the private dhcp server that is should be running on your
management node.

Secondly also make sure you have the dhcp server setup on your
management node for the private network.

Aaron

On Tue, Jun 19, 2012 at 5:53 PM, Michael Jinks <mji...@uchicago.edu>

wrote:

Hi, all.

Trying to resurrect a thread I started on Friday, subject 'Image capture
succeeds, then "fails"'. ?Mike Haudenschild helped me narrow down the
problem but so far I haven't been able to find a cause or a fix.

I'm trying to capture my first Linux VM. ?Things go along okay through
the capture stage, but (thanks Mike) we fail when VCL tries to reserve
and deploy the new image.

The critical message from the log appears to be:

?|17491|19:19|reload| ---- WARNING ----
?|17491|19:19|reload| 2012-06-19
?14:10:22|17491|19:19|reload|VMware.pm:load(395)|failed to prepare vmx
file for vcl-linux-template-2-bak on VM host: vcl0001
?|17491|19:19|reload| ( 0) VMware.pm, load (line: 395)
?|17491|19:19|reload| (-1) new.pm, reload_image (line: 618)
?|17491|19:19|reload| (-2) new.pm, process (line: 248)
?|17491|19:19|reload| (-3) vcld, make_new_child (line: 568)
?|17491|19:19|reload| (-4) vcld, main (line: 346)


Further down, I'll paste in a complete copy of the log mail I got from
this attempt.

Our VM storage settings for this VM host are:

?Repository Path: ? ? ? /vmfs/volumes/nfs-vcl-templates
?Data Store Path: ? ? ? /vmfs/volumes/T2_6045_dev_VCL_ds01
?VM Path: ? ? ? /vmfs/volumes/T2_6045_dev_VCL_ds01

(Note Data Store and VM are explicitly the same; we've also had VM Path
set to "(empty)" with no apparent difference in behavior.)

Both of those paths are writable on the hypervisor. ?During capture, a
VM directory appears in both locations. ?In the directory under the
Repository path, we have many vmdk files, sizes ranging from 842M to
1.5k, with names like:

?vmwarelinux-linuxtemplate2v1226-v0-s001.vmdk
?vmwarelinux-linuxtemplate2v1226-v0-s002.vmdk
?vmwarelinux-linuxtemplate2v1226-v0-s003.vmdk
?[...]
?vmwarelinux-linuxtemplate2v1226-v0-s016.vmdk
?vmwarelinux-linuxtemplate2v1226-v0.vmdk

My first guess is that we have one vmdk file for each attempted capture,
and this is a series of xdiffs on the original?

In the Data Store/VM directory, we have:

?# pwd
?/vmfs/volumes/T2_6045_dev_VCL_ds01/vmwarelinux-linuxtemplate2v1226-v0
?# ls -lh
?-rw------- ? ?1 root ?root ? 30.0G Jun 19 20:12
vmwarelinux-linuxtemplate2v1226-v0-flat.vmdk ?-rw------- ? ?1 root
?root ? ? 527 Jun 19 20:12 vmwarelinux-linuxtemplate2v1226-v0.vmdk

So, it seems that those locations are accessible and writable, and being
written. ?What else might cause the vmx file prep to fail? ?I went to
VMware.pm line 395, but that's a call to a subroutine, prepare_vmx(),
which is a fairly lengthy chunk of code and doesn't appear to be
dropping any breadcrumbs as it runs, only the failure message when it
exits. ?So stepping through that without guidance is going to be a
challenge.

Meanwhile we've also started trying to capture a Windows image. ?That's
dying too, but with a different set of error messages. ?I'll post that
under separate cover.

Thanks for any insight. ?Complete log message follows.
-m


reservation failed on vcl-linux-template-2-bak: process failed after
trying to load or make available
-----------------------------------------------------------------------
- time: 2012-06-19 14:10:22
caller: State.pm:reservation_failed(213)
( 0) State.pm, reservation_failed (line: 213)
(-1) new.pm, process (line: 298)
(-2) vcld, make_new_child (line: 568)
(-3) vcld, main (line: 346)
------------------------------------------------------------------------
management node: pilot-lab.uchicago.edu
reservation PID: 17491
parent vcld PID: 2491

request ID: 19
reservation ID: 19
request state/laststate: reload/image
request start time: 2012-06-19 14:10:12
request end time: 2012-06-19 14:40:12
for imaging: no
log ID: none

computer: vcl-linux-template-2-bak
computer id: 7
computer type: virtualmachine
computer eth0 MAC address: <undefined>
computer eth1 MAC address: <undefined>
computer private IP address: 10.50.84.15
computer public IP address: 10.50.84.15
computer in block allocation: no
provisioning module: VCL::Module::Provisioning::VMware::VMware

vm host: vcl0001
vm host ID: 1
vm host computer ID: 1
vm profile: VMware ESXi - IT Services
vm profile VM path: /vmfs/volumes/T2_6045_dev_VCL_ds01
vm profile repository path: /vmfs/volumes/nfs-vcl-templates
vm profile datastore path: /vmfs/volumes/T2_6045_dev_VCL_ds01
vm profile disk type: localdisk

image: vmwarelinux-linuxtemplate2v1226-v0
image display name: linux-template-2v12
image ID: 26
image revision ID: 22
image size: 30720 MB
use Sysprep: yes
root access: yes
image owner ID: 1
image owner affiliation: Local
image revision date created: 2012-06-19 14:08:20
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-06-19
14:10:20|17491|19:19|reload|VMware.pm:get_image_size_bytes(3841)|retrie
ved the size of the image from the datastore on the VM host:
32,212,255,247> >
2012-06-19 14:10:20|17491|19:19|reload|

VMware.pm:get_image_size_bytes(3851)|image size retrieved from both the image
repository and VM host datastore:

|17491|19:19|reload| image repository: 2,398,356,996
|17491|19:19|reload| VM host datastore: 32,212,255,247

2012-06-19 14:10:20|17491|19:19|reload|

VMware.pm:get_image_size_bytes(3871)|size of vmwarelinux-linuxtemplate2v1226-
v0 image:

|17491|19:19|reload| 32,212,255,247 bytes
|17491|19:19|reload| 30,720 MB
|17491|19:19|reload| 30.00 GB

2012-06-19
14:10:20|17491|19:19|reload|VMware.pm:get_vm_additional_vmx_bytes_requi
red(4713)|8053063811 additional bytes required for REDO files because VM
disk mode is NOT persistent> >
2012-06-19 14:10:20|17491|19:19|reload|

VMware.pm:get_vm_additional_vmx_bytes_required(4716)|estimate of additional
space required for the vmx directory:

|17491|19:19|reload| vmem/vswp file: 536,870,912 bytes, 512.0 MB, 0.50
|GB
|17491|19:19|reload| redo files: 8,053,063,811 bytes, 7,680.0 MB, 7.50
|GB
|17491|19:19|reload| total: 8,589,934,723 bytes, 8,192.0 MB, 8.00 GB

2012-06-19
14:10:20|17491|19:19|reload|Linux.pm:file_exists(1404)|'/vmfs/volumes/T
2_6045_dev_VCL_ds01/vmwarelinux-linuxtemplate2v1226-v0/vmwarelinux-linux
template2v1226-v0.vmdk' exists on vcl0001, files: 1, directories: 0,
links: 0 2012-06-19
14:10:20|17491|19:19|reload|VMware.pm:get_image_size_bytes(3819)|VM
profile vmdisk is set to 'localdisk', attempting to retrieve image size
from image repository 2012-06-19
14:10:21|17491|19:19|reload|Linux.pm:file_exists(1404)|'/vmfs/volumes/n
fs-vcl-templates' exists on vcl0001, files: 0, directories: 0, links: 1
2012-06-19
14:10:21|17491|19:19|reload|VMware.pm:is_repository_mounted_on_vmhost(5
485)|image repository is mounted on VM host vcl0001:
/vmfs/volumes/nfs-vcl-templates 2012-06-19
14:10:21|17491|19:19|reload|VMware.pm:get_image_size_bytes(3821)|checki
ng size of image in image repository mounted on VM host:
vcl0001:/vmfs/volumes/nfs-vcl-templates> >
2012-06-19 14:10:21|17491|19:19|reload|Linux.pm:get_file_size(2022)|size

of '/vmfs/volumes/nfs-vcl-templates/vmwarelinux-linuxtemplate2v1226-
v0/vmwarelinux-linuxtemplate2v1226-v0*.vmdk' on vcl0001:

|17491|19:19|reload| used: 2,398,356,996 bytes, 2,287.3 MB, 2.23 GB
|17491|19:19|reload| allocated: 3,605,390,848 bytes, 3,438.4 MB, 3.36 GB

2012-06-19 14:10:21|17491|19:19|reload|Linux.pm:get_file_size(2022)|size

of '/vmfs/volumes/T2_6045_dev_VCL_ds01/vmwarelinux-linuxtemplate2v1226-
v0/vmwarelinux-linuxtemplate2v1226-v0*.vmdk' on vcl0001:

|17491|19:19|reload| used: 32,212,255,247 bytes, 30,720.0 MB, 30.00 GB
|17491|19:19|reload| allocated: 32,212,320,256 bytes, 30,720.1 MB, 30.00
|GB

2012-06-19
14:10:21|17491|19:19|reload|VMware.pm:get_image_size_bytes(3841)|retrie
ved the size of the image from the datastore on the VM host:
32,212,255,247> >
2012-06-19 14:10:21|17491|19:19|reload|

VMware.pm:get_image_size_bytes(3851)|image size retrieved from both the image
repository and VM host datastore:

|17491|19:19|reload| image repository: 2,398,356,996
|17491|19:19|reload| VM host datastore: 32,212,255,247

2012-06-19 14:10:21|17491|19:19|reload|

VMware.pm:get_image_size_bytes(3871)|size of vmwarelinux-linuxtemplate2v1226-
v0 image:

|17491|19:19|reload| 32,212,255,247 bytes
|17491|19:19|reload| 30,720 MB
|17491|19:19|reload| 30.00 GB

2012-06-19
14:10:21|17491|19:19|reload|VMware.pm:get_vm_additional_vmdk_bytes_requ
ired(4657)|no additional space required for vmdk files because they
already exist on VM host 2012-06-19
14:10:21|17491|19:19|reload|VMware.pm:get_vm_additional_vmdk_bytes_requ
ired(4662)|VM requires appoximately 0 additional bytes (0 MB, 0 GB) of
disk space on the VM host for the vmdk directory 2012-06-19
14:10:21|17491|19:19|reload|VMware.pm:check_vmhost_disk_space(2070)|eno
ugh space is available on shared vmx/vmdk volume on VM host vcl0001:
'/vmfs/volumes/T2_6045_dev_VCL_ds01'> >
|17491|19:19|reload| vmx additional space required: ? ? ? ?
|?8,589,934,723 bytes, 8,192.0 MB, 8.00 GB 17491|19:19|reload| vmdk
|additional space required: ? ? ? ? 0 bytes, 0.0 MB, 0.00 GB
|17491|19:19|reload| total additional space required: ? ? ?
|?8,589,934,723 bytes, 8,192.0 MB, 8.00 GB 17491|19:19|reload| shared
|vmx/vmdk volume available space: 1,042,905,300,992 bytes, 994,592.0
|MB, 971.28 GB> >
2012-06-19
14:10:21|17491|19:19|reload|Module.pm:create_mn_os_object(335)|manageme
nt node OS object has already been created, address: 3997f10, returning
1 2012-06-19
14:10:21|17491|19:19|reload|Module.pm:new(203)|VCL::Module::Semaphore
object created, address: 3cd4360 2012-06-19
14:10:21|17491|19:19|reload|Module.pm:code_loop_timeout(742)|attempting
to open lockfile, maximum of 1200 seconds 2012-06-19
14:10:21|17491|19:19|reload|Module.pm:code_loop_timeout(759)|attempt 1:
attempting to open lockfile 2012-06-19
14:10:21|17491|19:19|reload|Semaphore.pm:open_lockfile(146)|opened and
obtained an exclusive lock on file:
/tmp/vcl0001-vmfs-volumes-T2_6045_dev_VCL_ds01-vmwarelinux-linuxtemplat
e2v1226-v0.lock 2012-06-19
14:10:21|17491|19:19|reload|Module.pm:code_loop_timeout(762)|attempting
to open lockfile, code returned true 2012-06-19
14:10:21|17491|19:19|reload|Module.pm:get_semaphore(844)|created
Semaphore object, memory address: 3cd4360 2012-06-19
14:10:22|17491|19:19|reload|Linux.pm:file_exists(1404)|'/vmfs/volumes/T
2_6045_dev_VCL_ds01/vmwarelinux-linuxtemplate2v1226-v0/vmwarelinux-linux
template2v1226-v0.vmdk' exists on vcl0001, files: 1, directories: 0,
links: 0 2012-06-19
14:10:22|17491|19:19|reload|VMware.pm:prepare_vmdk(1785)|VM is not
persistent and nonpersistent vmdk file already exists on VM host
vcl0001:
/vmfs/volumes/T2_6045_dev_VCL_ds01/vmwarelinux-linuxtemplate2v1226-v0/v
mwarelinux-linuxtemplate2v1226-v0.vmdk 2012-06-19
14:10:22|17491|19:19|reload|Semaphore.pm:release_lockfile(248)|deleted
file:
/tmp/vcl0001-vmfs-volumes-T2_6045_dev_VCL_ds01-vmwarelinux-linuxtemplat
e2v1226-v0.lock 2012-06-19
14:10:22|17491|19:19|reload|Semaphore.pm:DESTROY(281)|destroyed
Semaphore object, memory address: 3cd4360 2012-06-19
14:10:22|17491|19:19|reload|utils.pm:insertloadlog(3875)|inserted
computer=7, transfervm, copied vmwarelinux-linuxtemplate2v1226-v0 to
vcl-linux-template-2-bak 2012-06-19
14:10:22|17491|19:19|reload|VMware.pm:get_vm_ram(4306)|image ram
setting is too low: 0 MB, 512 MB will be used 2012-06-19
14:10:22|17491|19:19|reload|VMware.pm:get_vm_os_configuration(4210)|ret
rieved default VM configuration for OS: linux-x86_64> >
|17491|19:19|reload| : {
|17491|19:19|reload| : ? "ethernet-virtualDev" => "e1000",
|17491|19:19|reload| : ? "guestOS" => "otherlinux-64",
|17491|19:19|reload| : ? "scsi-virtualDev" => "lsiLogic"
|17491|19:19|reload| : }
|17491|19:19|reload| ---- WARNING ----
|17491|19:19|reload| 2012-06-19
|14:10:22|17491|19:19|reload|DataStructure.pm:_automethod(812)|correspo
|nding data has not been initialized for get_computer_eth0_mac_address:
|$self->request_data->{reservation}{19}{computer}{eth0macaddress}
|17491|19:19|reload| ( 0) DataStructure.pm, _automethod (line: 812)
|17491|19:19|reload| (-1) Autoload.pm, __ANON__ (line: 80)
|17491|19:19|reload| (-2) VMware.pm, prepare_vmx (line: 1457)
|17491|19:19|reload| (-3) VMware.pm, load (line: 394)
|17491|19:19|reload| (-4) new.pm, reload_image (line: 618)
|17491|19:19|reload| (-5) new.pm, process (line: 248)
|17491|19:19|reload| ---- WARNING ----
|17491|19:19|reload| 2012-06-19
|14:10:22|17491|19:19|reload|VMware.pm:load(395)|failed to prepare vmx
|file for vcl-linux-template-2-bak on VM host: vcl0001
|17491|19:19|reload| ( 0) VMware.pm, load (line: 395)
|17491|19:19|reload| (-1) new.pm, reload_image (line: 618)
|17491|19:19|reload| (-2) new.pm, process (line: 248)
|17491|19:19|reload| (-3) vcld, make_new_child (line: 568)
|17491|19:19|reload| (-4) vcld, main (line: 346)
|17491|19:19|reload| ---- WARNING ----
|17491|19:19|reload| 2012-06-19
|14:10:22|17491|19:19|reload|new.pm:reload_image(623)|vmwarelinux-linux
|template2v1226-v0 failed to load on vcl-linux-template-2-bak, returning
|17491|19:19|reload| ( 0) new.pm, reload_image (line: 623)
|17491|19:19|reload| (-1) new.pm, process (line: 248)
|17491|19:19|reload| (-2) vcld, make_new_child (line: 568)
|17491|19:19|reload| (-3) vcld, main (line: 346)

2012-06-19
14:10:22|17491|19:19|reload|utils.pm:insertloadlog(3875)|inserted
computer=7, loadimagefailed, vmwarelinux-linuxtemplate2v1226-v0 failed
to load on vcl-linux-template-2-bak> >
|17491|19:19|reload| ---- WARNING ----
|17491|19:19|reload| 2012-06-19
|14:10:22|17491|19:19|reload|new.pm:process(295)|failed to load
|vcl-linux-template-2-bak with vmwarelinux-linuxtemplate2v1226-v0
|17491|19:19|reload| ( 0) new.pm, process (line: 295)
|17491|19:19|reload| (-1) vcld, make_new_child (line: 568)
|17491|19:19|reload| (-2) vcld, main (line: 346)

2012-06-19
14:10:22|17491|19:19|reload|DataStructure.pm:get_computer_state_name(23
05)|attempting to retrieve current state of computer
vcl-linux-template-2-bak from the database 2012-06-19
14:10:22|17491|19:19|reload|DataStructure.pm:get_computer_state_name(23
36)|retrieved current state of computer vcl-linux-template-2-bak from
the database: reloading 2012-06-19
14:10:22|17491|19:19|reload|DataStructure.pm:_automethod(834)|data
structure updated:
$self->request_data->{reservation}{19}{computer}{state}{name}> >
|17491|19:19|reload| computer_state_name = reloading

2012-06-19
14:10:22|17491|19:19|reload|DataStructure.pm:get_computer_private_ip_ad
dress(1581)|attempting to retrieve private IP address for computer:
vcl-linux-template-2-bak 2012-06-19
14:10:22|17491|19:19|reload|DataStructure.pm:get_computer_private_ip_ad
dress(1585)|retrieved contents of /etc/hosts on this management node,
contains 18 lines 2012-06-19
14:10:22|17491|19:19|reload|DataStructure.pm:get_computer_private_ip_ad
dress(1645)|returning IP address from /etc/hosts file: 10.50.84.15
2012-06-19
14:10:22|17491|19:19|reload|utils.pm:is_inblockrequest(6163)|zero rows
were returned from database select 2012-06-19
14:10:22|17491|19:19|reload|DataStructure.pm:get_image_affiliation_name
(2035)|image owner id: 1 2012-06-19
14:10:22|17491|19:19|reload|utils.pm:getnewdbh(2709)|database requested
(information_schema) does not match handle stored in $ENV{dbh}
(vcl:128.135.107.122) 2012-06-19
14:10:22|17491|19:19|reload|utils.pm:getnewdbh(2760)|database handle
stored in $ENV{dbh} 2012-06-19
14:10:22|17491|19:19|reload|DataStructure.pm:retrieve_user_data(1352)|a
ttempting to retrieve and store data for user: user.id = '1' 2012-06-19
14:10:22|17491|19:19|reload|utils.pm:getnewdbh(2709)|database requested
(vcl) does not match handle stored in $ENV{dbh}
(information_schema:128.135.107.122) 2012-06-19
14:10:22|17491|19:19|reload|utils.pm:getnewdbh(2760)|database handle
stored in $ENV{dbh} 2012-06-19
14:10:22|17491|19:19|reload|DataStructure.pm:retrieve_user_data(1415)|d
ata has been retrieved for user: admin (id: 1)

- --
- -------------------------------
Josh Thompson
VCL Developer
North Carolina State University

my GPG/PGP key can be found at pgp.mit.edu

All electronic mail messages in connection with State business which
are sent to or received by this account are subject to the NC Public
Records Law and may be disclosed to third parties.
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2.0.17 (GNU/Linux)

iEYEARECAAYFAk/h2yoACgkQV/LQcNdtPQNYCwCfcWNdBbopf+RZXv8XaW7vbSVM
DukAn2Jf9bCwqoObueZtHRDydTevhMX1
=ucyU
-----END PGP SIGNATURE-----




























					Reply via email to