You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@vcl.apache.org by Michael Jinks <mj...@uchicago.edu> on 2012/06/25 18:49:48 UTC
FIXED, Re: VCL image capture dies, "failed to prepare vmx file"
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 :: mjinks@uchicago.edu :: 773-469-9688
University of Chicago IT Services