I think I may have just run my first successful image capture.  There's
an image directory now in my templates directory, and when I browse to
"Manage Images" and "Edit Image Profiles", my base image is there.
Hooray!

...But, shortly after the capture completed, our admin address received
the message below.  I'm forwarding the whole thing because reading it
myself I don't see anything that looks like a statement of a problem,
except for the first "reservation failed" line.  Any idea what went
wrong?  Or, maybe nothing went wrong and this is a spurious error?

Where would I look for clues?

Thanks,
--Michael



----- Forwarded message from r...@pilot-lab.uchicago.edu -----


reservation failed on vcl-linux-template-2-bak: process failed after trying to 
load or make available
------------------------------------------------------------------------
time: 2012-06-15 15:31:21
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: 32473
parent vcld PID: 2506

request ID: 14
reservation ID: 14
request state/laststate: reload/image
request start time: 2012-06-15 15:31:12
request end time: 2012-06-15 16:01: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-Linuxtemplate2v218-v0
image display name: Linux template 2v2
image ID: 18
image revision ID: 16
image size: 30720 MB
use Sysprep: yes
root access: yes
image owner ID: 1
image owner affiliation: Local
image revision date created: 2012-06-15 15:29:23
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-15 
15:31:19|32473|14:14|reload|VMware.pm:get_image_size_bytes(3841)|retrieved the 
size of the image from the datastore on the VM host: 32,212,255,246
2012-06-15 
15:31:19|32473|14:14|reload|VMware.pm:get_image_size_bytes(3851)|image size 
retrieved from both the image repository and VM host datastore:
|32473|14:14|reload| image repository: 2,397,636,084
|32473|14:14|reload| VM host datastore: 32,212,255,246
2012-06-15 
15:31:19|32473|14:14|reload|VMware.pm:get_image_size_bytes(3871)|size of 
vmwarelinux-Linuxtemplate2v218-v0 image:
|32473|14:14|reload| 32,212,255,246 bytes
|32473|14:14|reload| 30,720 MB
|32473|14:14|reload| 30.00 GB
2012-06-15 
15:31:19|32473|14:14|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-15 
15:31:19|32473|14:14|reload|VMware.pm:get_vm_additional_vmx_bytes_required(4716)|estimate
 of additional space required for the vmx directory:
|32473|14:14|reload| vmem/vswp file: 536,870,912 bytes, 512.0 MB, 0.50 GB
|32473|14:14|reload| redo files: 8,053,063,811 bytes, 7,680.0 MB, 7.50 GB
|32473|14:14|reload| total: 8,589,934,723 bytes, 8,192.0 MB, 8.00 GB
2012-06-15 
15:31:19|32473|14:14|reload|Linux.pm:file_exists(1404)|'/vmfs/volumes/T2_6045_dev_VCL_ds01/vmwarelinux-Linuxtemplate2v218-v0/vmwarelinux-Linuxtemplate2v218-v0.vmdk'
 exists on vcl0001, files: 1, directories: 0, links: 0
2012-06-15 15:31:19|32473|14:14|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-15 
15:31:20|32473|14:14|reload|Linux.pm:file_exists(1404)|'/vmfs/volumes/nfs-vcl-templates'
 exists on vcl0001, files: 0, directories: 0, links: 1
2012-06-15 
15:31:20|32473|14:14|reload|VMware.pm:is_repository_mounted_on_vmhost(5485)|image
 repository is mounted on VM host vcl0001: /vmfs/volumes/nfs-vcl-templates
2012-06-15 
15:31:20|32473|14:14|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-15 15:31:20|32473|14:14|reload|Linux.pm:get_file_size(2022)|size of 
'/vmfs/volumes/nfs-vcl-templates/vmwarelinux-Linuxtemplate2v218-v0/vmwarelinux-Linuxtemplate2v218-v0*.vmdk'
 on vcl0001:
|32473|14:14|reload| used: 2,397,636,084 bytes, 2,286.6 MB, 2.23 GB
|32473|14:14|reload| allocated: 3,604,186,624 bytes, 3,437.2 MB, 3.36 GB
2012-06-15 15:31:20|32473|14:14|reload|Linux.pm:get_file_size(2022)|size of 
'/vmfs/volumes/T2_6045_dev_VCL_ds01/vmwarelinux-Linuxtemplate2v218-v0/vmwarelinux-Linuxtemplate2v218-v0*.vmdk'
 on vcl0001:
|32473|14:14|reload| used: 32,212,255,246 bytes, 30,720.0 MB, 30.00 GB
|32473|14:14|reload| allocated: 32,212,320,256 bytes, 30,720.1 MB, 30.00 GB
2012-06-15 
15:31:20|32473|14:14|reload|VMware.pm:get_image_size_bytes(3841)|retrieved the 
size of the image from the datastore on the VM host: 32,212,255,246
2012-06-15 
15:31:20|32473|14:14|reload|VMware.pm:get_image_size_bytes(3851)|image size 
retrieved from both the image repository and VM host datastore:
|32473|14:14|reload| image repository: 2,397,636,084
|32473|14:14|reload| VM host datastore: 32,212,255,246
2012-06-15 
15:31:20|32473|14:14|reload|VMware.pm:get_image_size_bytes(3871)|size of 
vmwarelinux-Linuxtemplate2v218-v0 image:
|32473|14:14|reload| 32,212,255,246 bytes
|32473|14:14|reload| 30,720 MB
|32473|14:14|reload| 30.00 GB
2012-06-15 
15:31:20|32473|14:14|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-15 
15:31:20|32473|14:14|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-15 
15:31:20|32473|14:14|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'
|32473|14:14|reload| vmx additional space required:          8,589,934,723 
bytes, 8,192.0 MB, 8.00 GB
|32473|14:14|reload| vmdk additional space required:         0 bytes, 0.0 MB, 
0.00 GB
|32473|14:14|reload| total additional space required:        8,589,934,723 
bytes, 8,192.0 MB, 8.00 GB
|32473|14:14|reload| shared vmx/vmdk volume available space: 1,042,964,021,248 
bytes, 994,648.0 MB, 971.34 GB
2012-06-15 
15:31:20|32473|14:14|reload|Module.pm:create_mn_os_object(335)|management node 
OS object has already been created, address: 4062100, returning 1
2012-06-15 
15:31:20|32473|14:14|reload|Module.pm:new(203)|VCL::Module::Semaphore object 
created, address: 439d570
2012-06-15 
15:31:20|32473|14:14|reload|Module.pm:code_loop_timeout(742)|attempting to open 
lockfile, maximum of 1200 seconds
2012-06-15 15:31:20|32473|14:14|reload|Module.pm:code_loop_timeout(759)|attempt 
1: attempting to open lockfile
2012-06-15 15:31:20|32473|14:14|reload|Semaphore.pm:open_lockfile(146)|opened 
and obtained an exclusive lock on file: 
/tmp/vcl0001-vmfs-volumes-T2_6045_dev_VCL_ds01-vmwarelinux-Linuxtemplate2v218-v0.lock
2012-06-15 
15:31:20|32473|14:14|reload|Module.pm:code_loop_timeout(762)|attempting to open 
lockfile, code returned true
2012-06-15 15:31:20|32473|14:14|reload|Module.pm:get_semaphore(844)|created 
Semaphore object, memory address: 439d570
2012-06-15 
15:31:21|32473|14:14|reload|Linux.pm:file_exists(1404)|'/vmfs/volumes/T2_6045_dev_VCL_ds01/vmwarelinux-Linuxtemplate2v218-v0/vmwarelinux-Linuxtemplate2v218-v0.vmdk'
 exists on vcl0001, files: 1, directories: 0, links: 0
2012-06-15 15:31:21|32473|14:14|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-Linuxtemplate2v218-v0/vmwarelinux-Linuxtemplate2v218-v0.vmdk
2012-06-15 
15:31:21|32473|14:14|reload|Semaphore.pm:release_lockfile(248)|deleted file: 
/tmp/vcl0001-vmfs-volumes-T2_6045_dev_VCL_ds01-vmwarelinux-Linuxtemplate2v218-v0.lock
2012-06-15 15:31:21|32473|14:14|reload|Semaphore.pm:DESTROY(281)|destroyed 
Semaphore object, memory address: 439d570
2012-06-15 15:31:21|32473|14:14|reload|utils.pm:insertloadlog(3875)|inserted 
computer=7, transfervm, copied vmwarelinux-Linuxtemplate2v218-v0 to 
vcl-linux-template-2-bak
2012-06-15 15:31:21|32473|14:14|reload|VMware.pm:get_vm_ram(4306)|image ram 
setting is too low: 0 MB, 512 MB will be used
2012-06-15 
15:31:21|32473|14:14|reload|VMware.pm:get_vm_os_configuration(4210)|retrieved 
default VM configuration for OS: linux-x86_64
|32473|14:14|reload| : {
|32473|14:14|reload| :   "ethernet-virtualDev" => "e1000",
|32473|14:14|reload| :   "guestOS" => "otherlinux-64",
|32473|14:14|reload| :   "scsi-virtualDev" => "lsiLogic"
|32473|14:14|reload| : }
|32473|14:14|reload| ---- WARNING ---- 
|32473|14:14|reload| 2012-06-15 
15:31:21|32473|14:14|reload|DataStructure.pm:_automethod(812)|corresponding 
data has not been initialized for get_computer_eth0_mac_address: 
$self->request_data->{reservation}{14}{computer}{eth0macaddress}
|32473|14:14|reload| ( 0) DataStructure.pm, _automethod (line: 812)
|32473|14:14|reload| (-1) Autoload.pm, __ANON__ (line: 80)
|32473|14:14|reload| (-2) VMware.pm, prepare_vmx (line: 1457)
|32473|14:14|reload| (-3) VMware.pm, load (line: 394)
|32473|14:14|reload| (-4) new.pm, reload_image (line: 618)
|32473|14:14|reload| (-5) new.pm, process (line: 248)
|32473|14:14|reload| ---- WARNING ---- 
|32473|14:14|reload| 2012-06-15 
15:31:21|32473|14:14|reload|VMware.pm:load(395)|failed to prepare vmx file for 
vcl-linux-template-2-bak on VM host: vcl0001
|32473|14:14|reload| ( 0) VMware.pm, load (line: 395)
|32473|14:14|reload| (-1) new.pm, reload_image (line: 618)
|32473|14:14|reload| (-2) new.pm, process (line: 248)
|32473|14:14|reload| (-3) vcld, make_new_child (line: 568)
|32473|14:14|reload| (-4) vcld, main (line: 346)
|32473|14:14|reload| ---- WARNING ---- 
|32473|14:14|reload| 2012-06-15 
15:31:21|32473|14:14|reload|new.pm:reload_image(623)|vmwarelinux-Linuxtemplate2v218-v0
 failed to load on vcl-linux-template-2-bak, returning
|32473|14:14|reload| ( 0) new.pm, reload_image (line: 623)
|32473|14:14|reload| (-1) new.pm, process (line: 248)
|32473|14:14|reload| (-2) vcld, make_new_child (line: 568)
|32473|14:14|reload| (-3) vcld, main (line: 346)
2012-06-15 15:31:21|32473|14:14|reload|utils.pm:insertloadlog(3875)|inserted 
computer=7, loadimagefailed, vmwarelinux-Linuxtemplate2v218-v0 failed to load 
on vcl-linux-template-2-bak
|32473|14:14|reload| ---- WARNING ---- 
|32473|14:14|reload| 2012-06-15 
15:31:21|32473|14:14|reload|new.pm:process(295)|failed to load 
vcl-linux-template-2-bak with vmwarelinux-Linuxtemplate2v218-v0
|32473|14:14|reload| ( 0) new.pm, process (line: 295)
|32473|14:14|reload| (-1) vcld, make_new_child (line: 568)
|32473|14:14|reload| (-2) vcld, main (line: 346)
2012-06-15 
15:31:21|32473|14:14|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-15 
15:31:21|32473|14:14|reload|DataStructure.pm:get_computer_state_name(2336)|retrieved
 current state of computer vcl-linux-template-2-bak from the database: reloading
2012-06-15 15:31:21|32473|14:14|reload|DataStructure.pm:_automethod(834)|data 
structure updated: $self->request_data->{reservation}{14}{computer}{state}{name}
|32473|14:14|reload| computer_state_name = reloading
2012-06-15 
15:31:21|32473|14:14|reload|DataStructure.pm:get_computer_private_ip_address(1581)|attempting
 to retrieve private IP address for computer: vcl-linux-template-2-bak
2012-06-15 
15:31:21|32473|14:14|reload|DataStructure.pm:get_computer_private_ip_address(1585)|retrieved
 contents of /etc/hosts on this management node, contains 17 lines
2012-06-15 
15:31:21|32473|14:14|reload|DataStructure.pm:get_computer_private_ip_address(1645)|returning
 IP address from /etc/hosts file: 10.50.84.15
2012-06-15 15:31:21|32473|14:14|reload|utils.pm:is_inblockrequest(6163)|zero 
rows were returned from database select
2012-06-15 
15:31:21|32473|14:14|reload|DataStructure.pm:get_image_affiliation_name(2035)|image
 owner id: 1
2012-06-15 15:31:21|32473|14:14|reload|utils.pm:getnewdbh(2709)|database 
requested (information_schema) does not match handle stored in $ENV{dbh} 
(vcl:128.135.107.122)
2012-06-15 15:31:21|32473|14:14|reload|utils.pm:getnewdbh(2760)|database handle 
stored in $ENV{dbh}
2012-06-15 
15:31:21|32473|14:14|reload|DataStructure.pm:retrieve_user_data(1352)|attempting
 to retrieve and store data for user: user.id = '1'
2012-06-15 15:31:21|32473|14:14|reload|utils.pm:getnewdbh(2709)|database 
requested (vcl) does not match handle stored in $ENV{dbh} 
(information_schema:128.135.107.122)
2012-06-15 15:31:21|32473|14:14|reload|utils.pm:getnewdbh(2760)|database handle 
stored in $ENV{dbh}
2012-06-15 
15:31:21|32473|14:14|reload|DataStructure.pm:retrieve_user_data(1415)|data has 
been retrieved for user: admin (id: 1)

----- End forwarded message -----

-- 
Michael Jinks :: mji...@uchicago.edu :: 773-469-9688
University of Chicago IT Services

Reply via email to