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)
