For the record: the trouble was that we didn't have defined MAC
addresses in our database records for these VM's.
Adding the MAC addresses to the computer database by hand fixed the
issue.
On Tue, Jun 19, 2012 at 04:53:40PM -0500, Michael Jinks 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)
>
--
Michael Jinks :: mji...@uchicago.edu :: 773-469-9688
University of Chicago IT Services
