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)|retrieved 
> 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_required(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/T2_6045_dev_VCL_ds01/vmwarelinux-linuxtemplate2v1226-v0/vmwarelinux-linuxtemplate2v1226-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/nfs-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(5485)|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)|checking 
> 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)|retrieved 
> 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_required(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_required(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)|enough 
> 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)|management 
> 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-linuxtemplate2v1226-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/T2_6045_dev_VCL_ds01/vmwarelinux-linuxtemplate2v1226-v0/vmwarelinux-linuxtemplate2v1226-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/vmwarelinux-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-linuxtemplate2v1226-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)|retrieved 
> 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)|corresponding 
> 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-linuxtemplate2v1226-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(2305)|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(2336)|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_address(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_address(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_address(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)|attempting
>  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)|data 
> has been retrieved for user: admin (id: 1)
>



-- 
Aaron Peeler
Program Manager
Virtual Computing Lab
NC State University

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.

Reply via email to