Hi Andy,
As stated in the previous email, I also tried to update and save an Windows
7 image. Similar exception (not exactly the same) is found in the vcld.log:
2014-07-25
19:24:41|28097|118:118|image|vSphere_SDK.pm:copy_virtual_disk(922)|deleting
cloned VM file:
/vmfs/volumes/vmware_images_1/vmwarewin7-Windows7_Vivie9-v0/vmwarewin7-Windows7_Vivie9-v0.vmsd
2014-07-25
19:24:41|28097|118:118|image|vSphere_SDK.pm:delete_file(1596)|attempting to
delete file: [vmware_images_1]
vmwarewin7-Windows7_Vivie9-v0/vmwarewin7-Windows7_Vivie9-v0.vmsd
2014-07-25
19:24:43|28097|118:118|image|vSphere_SDK.pm:delete_file(1609)|deleted file:
[vmware_images_1]
vmwarewin7-Windows7_Vivie9-v0/vmwarewin7-Windows7_Vivie9-v0.vmsd
2014-07-25
19:24:43|28097|118:118|image|vSphere_SDK.pm:copy_virtual_disk(922)|deleting
cloned VM file:
/vmfs/volumes/vmware_images_1/vmwarewin7-Windows7_Vivie9-v0/vmwarewin7-Windows7_Vivie9-v0.vmx
2014-07-25
19:24:43|28097|118:118|image|vSphere_SDK.pm:delete_file(1596)|attempting to
delete file: [vmware_images_1]
vmwarewin7-Windows7_Vivie9-v0/vmwarewin7-Windows7_Vivie9-v0.vmx
2014-07-25
19:24:45|28097|118:118|image|vSphere_SDK.pm:delete_file(1609)|deleted file:
[vmware_images_1]
vmwarewin7-Windows7_Vivie9-v0/vmwarewin7-Windows7_Vivie9-v0.vmx
2014-07-25
19:24:45|28097|118:118|image|vSphere_SDK.pm:copy_virtual_disk(922)|deleting
cloned VM file:
/vmfs/volumes/vmware_images_1/vmwarewin7-Windows7_Vivie9-v0/vmwarewin7-Windows7_Vivie9-v0.vmxf
2014-07-25
19:24:45|28097|118:118|image|vSphere_SDK.pm:delete_file(1596)|attempting to
delete file: [vmware_images_1]
vmwarewin7-Windows7_Vivie9-v0/vmwarewin7-Windows7_Vivie9-v0.vmxf
2014-07-25
19:24:47|28097|118:118|image|vSphere_SDK.pm:delete_file(1609)|deleted file:
[vmware_images_1]
vmwarewin7-Windows7_Vivie9-v0/vmwarewin7-Windows7_Vivie9-v0.vmxf
2014-07-25
19:24:47|28097|118:118|image|vSphere_SDK.pm:copy_virtual_disk(930)|copied
virtual disk on VM host vcl-vcenter-1: '[vmware_vms_1]
vm0-10_4-v2/vmwarewin7-pro64bit4-v2-000001.vmdk' --> '[vmware_images_1]
vmwarewin7-Windows7_VivienTest9-v0/vmwarewin7-Windows7_VivienTest9-v0.vmdk'
2014-07-25 19:24:47|28097|118:118|image|VMware.pm:copy_vmdk(5825)|copied
vmdk using API's copy_virtual_disk subroutine
2014-07-25 19:24:47|28097|118:118|image|utils.pm:update_image_name(6307)|updated
image.name and imagerevision.imagename in database to
'vmwarewin7-Windows7_Vivie9-v0' for image ID: 9, imagerevision ID: 13
2014-07-25
19:24:47|28097|118:118|image|DataStructure.pm:_automethod(847)|data
structure updated, hash path:
$self->request_data->{reservation}{118}{imagerevision}{imagename}, data
identifier: image_name, data:
|28097|118:118|image| : "vmwarewin7-Windows7_Vivie9-v0"
2014-07-25 19:24:47|28097|118:118|image|VMware.pm:copy_vmdk(5835)|updated
image name to vmwarewin7-Windows7_Vivie9-v0
2014-07-25
19:24:47|28097|118:118|image|vSphere_SDK.pm:_get_file_info(2520)|searching
for matching file paths: base directory path: '[vmware_vms_1] vm0-10_4-v2',
search pattern: 'vmwarewin7-Windows7_VivienTest9-v0.vmx.reference'
2014-07-25
19:24:49|28097|118:118|image|vSphere_SDK.pm:_get_file_info(2575)|retrieved
info for 0 matching files:
|28097|118:118|image| : {}
2014-07-25
19:24:49|28097|118:118|image|vSphere_SDK.pm:find_files(2120)|matching file
count: 0
2014-07-25
19:24:49|28097|118:118|image|vSphere_SDK.pm:file_exists(1992)|file does not
exist: [vmware_vms_1]
vm0-10_4-v2/vmwarewin7-Windows7_VivienTest9-v0.vmx.reference
2014-07-25 19:24:49|28097|118:118|image|VMware.pm:copy_vmdk(6089)|reference
vmx file not copied to vmdk directory because it does not exist:
'/vmfs/volumes/vmware_vms_1/vm0-10_4-v2/vmwarewin7-Windows7_VivienTest9-v0.vmx.reference'
2014-07-25
19:24:49|28097|118:118|image|vSphere_SDK.pm:_get_file_info(2520)|searching
for matching file paths: base directory path: '[vmware_images_1]
vmwarewin7-Windows7_VivienTest9-v0', search pattern:
'vmwarewin7-Windows7_VivienTest9-v0*.vmdk'
2014-07-25
19:24:51|28097|118:118|image|vSphere_SDK.pm:_get_file_info(2531)|base
directory does not exist: '[vmware_images_1]
vmwarewin7-Windows7_VivienTest9-v0'
2014-07-25
19:24:51|28097|118:118|image|vSphere_SDK.pm:get_file_size(2044)|unable to
determine size of file on vcl-vcenter-1 because it does not exist:
/vmfs/volumes/vmware_images_1/vmwarewin7-Windows7_VivienTest9-v0/vmwarewin7-Windows7_VivienTest9-v0*.vmdk
|28097|118:118|image| ---- WARNING ----
|28097|118:118|image| 2014-07-25
19:24:51|28097|118:118|image|VMware.pm:copy_vmdk(6097)|copied vmdk on VM
host vcl-vcenter-1 but failed to retrieve destination file size:
|28097|118:118|image|
'/vmfs/volumes/vmware_vms_1/vm0-10_4-v2/vmwarewin7-pro64bit4-v2-000001.vmdk'
-->
'/vmfs/volumes/vmware_images_1/vmwarewin7-Windows7_VivienTest9-v0/vmwarewin7-Windows7_VivienTest9-v0.vmdk'
|28097|118:118|image| ( 0) VMware.pm, copy_vmdk (line: 6097)
|28097|118:118|image| (-1) VMware.pm, capture (line: 744)
|28097|118:118|image| (-2) image.pm, process (line: 162)
|28097|118:118|image| (-3) vcld, make_new_child (line: 571)
|28097|118:118|image| (-4) vcld, main (line: 350)
2014-07-25
19:24:51|28097|118:118|image|vSphere_SDK.pm:_get_file_info(2520)|searching
for matching file paths: base directory path: '[vmware_images_1]', search
pattern: 'vmwarewin7-Windows7_VivienTest9-v0'
2014-07-25
19:24:53|28097|118:118|image|vSphere_SDK.pm:_get_file_info(2575)|retrieved
info for 0 matching files:
|28097|118:118|image| : {}
2014-07-25
19:24:53|28097|118:118|image|vSphere_SDK.pm:find_files(2120)|matching file
count: 0
2014-07-25
19:24:53|28097|118:118|image|vSphere_SDK.pm:file_exists(1992)|file does not
exist: [vmware_images_1] vmwarewin7-Windows7_VivienTest9-v0
2014-07-25
19:24:53|28097|118:118|image|vSphere_SDK.pm:create_directory(1546)|created
directory: '[vmware_images_1] vmwarewin7-Windows7_VivienTest9-v0'
2014-07-25
19:24:53|28097|118:118|image|vSphere_SDK.pm:copy_file(1652)|attempting to
copy file on VM host vcl-vcenter-1: '[vmware_vms_1]
vm0-10_4-v2/vm0-10_4-v2.vmx' --> '[vmware_images_1]
vmwarewin7-Windows7_VivienTest9-v0/vmwarewin7-Windows7_VivienTest9-v0.vmx.reference'
2014-07-25
19:24:55|28097|118:118|image|vSphere_SDK.pm:copy_file(1676)|copied file on
VM host vcl-vcenter-1: '[vmware_vms_1] vm0-10_4-v2/vm0-10_4-v2.vmx' -->
'[vmware_images_1]
vmwarewin7-Windows7_VivienTest9-v0/vmwarewin7-Windows7_VivienTest9-v0.vmx.reference'
2014-07-25 19:24:55|28097|118:118|image|VMware.pm:capture(770)|vmdk will be
copied directly from VM host vcl-vcenter-1 to the image repository in the
2gbsparse disk format
2014-07-25
19:24:55|28097|118:118|image|vSphere_SDK.pm:_get_file_info(2520)|searching
for matching file paths: base directory path: '[vmware_images_1]
vmwarewin7-Windows7_VivienTest9-v0', search pattern:
'vmwarewin7-Windows7_VivienTest9-v0.vmdk'
2014-07-25
19:24:58|28097|118:118|image|vSphere_SDK.pm:_get_file_info(2575)|retrieved
info for 0 matching files:
|28097|118:118|image| : {}
2014-07-25
19:24:58|28097|118:118|image|vSphere_SDK.pm:find_files(2120)|matching file
count: 0
2014-07-25
19:24:58|28097|118:118|image|vSphere_SDK.pm:file_exists(1992)|file does not
exist: [vmware_images_1]
vmwarewin7-Windows7_VivienTest9-v0/vmwarewin7-Windows7_VivienTest9-v0.vmdk
|28097|118:118|image| ---- WARNING ----
|28097|118:118|image| 2014-07-25
19:24:58|28097|118:118|image|VMware.pm:copy_vmdk(5806)|source vmdk file
path does not exist on VM host vcl-vcenter-1:
/vmfs/volumes/vmware_images_1/vmwarewin7-Windows7_VivienTest9-v0/vmwarewin7-Windows7_VivienTest9-v0.vmdk
|28097|118:118|image| ( 0) VMware.pm, copy_vmdk (line: 5806)
|28097|118:118|image| (-1) VMware.pm, capture (line: 774)
|28097|118:118|image| (-2) image.pm, process (line: 162)
|28097|118:118|image| (-3) vcld, make_new_child (line: 571)
|28097|118:118|image| (-4) vcld, main (line: 350)
|28097|118:118|image| ---- WARNING ----
|28097|118:118|image| 2014-07-25
19:24:58|28097|118:118|image|VMware.pm:capture(778)|failed to copy the vmdk
files to the repository mounted on the VM host after the VM was powered
off:
'/vmfs/volumes/vmware_images_1/vmwarewin7-Windows7_VivienTest9-v0/vmwarewin7-Windows7_VivienTest9-v0.vmdk'
-->
'/vmfs/volumes/repository/vmwarewin7-Windows7_Vivie9-v0/vmwarewin7-Windows7_Vivie9-v0.vmdk'
|28097|118:118|image| ( 0) VMware.pm, capture (line: 778)
|28097|118:118|image| (-1) image.pm, process (line: 162)
|28097|118:118|image| (-2) vcld, make_new_child (line: 571)
|28097|118:118|image| (-3) vcld, main (line: 350)
2014-07-25 19:24:58|28097|118:118|image|VMware.pm:capture(870)|attempting
to delete directory where moved vmdk resided before reverting the name back
to the original:
/vmfs/volumes/vmware_images_1/vmwarewin7-Windows7_VivienTest9-v0
2014-07-25
19:24:58|28097|118:118|image|vSphere_SDK.pm:delete_file(1596)|attempting to
delete file: [vmware_images_1] vmwarewin7-Windows7_VivienTest9-v0
2014-07-25
19:25:00|28097|118:118|image|vSphere_SDK.pm:delete_file(1609)|deleted file:
[vmware_images_1] vmwarewin7-Windows7_VivienTest9-v0
2014-07-25 19:25:00|28097|118:118|image|VMware.pm:capture(876)|attempting
to power the VM back on so that it can be captured again
2014-07-25
19:25:02|28097|118:118|image|vSphere_SDK.pm:vm_power_on(379)|powered on VM:
[vmware_vms_1] vm0-10_4-v2/vm0-10_4-v2.vmx
|28097|118:118|image| ---- WARNING ----
|28097|118:118|image| 2014-07-25
19:25:02|28097|118:118|image|image.pm:process(166)|vmwarewin7-Windows7_VivienTest9-v0
image failed to be captured by provisioning module
|28097|118:118|image| ( 0) image.pm, process (line: 166)
|28097|118:118|image| (-1) vcld, make_new_child (line: 571)
|28097|118:118|image| (-2) vcld, main (line: 350)
2014-07-25
19:25:02|28097|118:118|image|utils.pm:get_management_node_info(5456)|retrieving
current management node info for 'vcl-mgmtnode-1' from database, cached
data is stale: 348 seconds old
2014-07-25
19:25:02|28097|118:118|image|utils.pm:get_management_node_info(5603)|retrieved
management node info: 'vcl-mgmtnode-1' (vcl-mgmtnode-1)
|28097|118:118|image| ---- CRITICAL ----
|28097|118:118|image| 2014-07-25
19:25:02|28097|118:118|image|image.pm:reservation_failed(387)|vmwarewin7-Windows7_Vivie9-v0
image creation failed
|28097|118:118|image| ( 0) image.pm, reservation_failed (line: 387)
|28097|118:118|image| (-1) image.pm, process (line: 167)
|28097|118:118|image| (-2) vcld, make_new_child (line: 571)
|28097|118:118|image| (-3) vcld, main (line: 350)
2014-07-25 19:25:02|28097|118:118|image|utils.pm:mail(1266)|SUCCESS --
Sending mail To: [email protected], VCL -- NOTICE DELAY Image Creation
Windows7_VivienTest
2014-07-25
19:25:02|28097|118:118|image|utils.pm:update_request_state(1545)|request
118 state updated to: maintenance, laststate to: image
2014-07-25 19:25:02|28097|118:118|image|image.pm:reservation_failed(441)|request
state set to maintenance, laststate to image
2014-07-25
19:25:02|28097|118:118|image|utils.pm:update_computer_state(1587)|computer
2 state updated to: maintenance
2014-07-25 19:25:02|28097|118:118|image|image.pm:reservation_failed(449)|vm0-10
state set to maintenance
2014-07-25 19:25:02|28097|118:118|image|image.pm:
reservation_failed(456)|exiting
2014-07-25
19:25:02|28097|118:118|image|utils.pm:delete_computerloadlog_reservation(6396)|removing
computerloadlog entries matching loadstate = begin
2014-07-25
19:25:02|28097|118:118|image|utils.pm:delete_computerloadlog_reservation(6443)|deleted
rows from computerloadlog for reservation id=118
2014-07-25 19:25:02|28097|118:118|image|State.pm:DESTROY(929)|VCL::image
process duration: 595 seconds
On Fri, Jul 25, 2014 at 6:47 PM, X.W. Liu <[email protected]> wrote:
> Hi Andy,
>
> Thanks a lot for the solution.
>
> It did solve the mismatch issue on the management node. I relaunched the
> image capturing process by changing the request.stateid from 10 to 16 for
> ID 117 as you instructed, but it seems another problem occurred. The
> following log has exception related to copying vmdk files. Could you please
> suggest me what to check next? Thanks.
>
> [root@vcl-mgmtnode-1 etc]# tail -f /var/log/vcld.log | grep "117:117"
> 2014-07-25
> 18:02:05|22101|117:117|image|Module.pm:code_loop_timeout(887)|waiting for
> vm0-34 to respond to SSH, maximum of 0 seconds
> 2014-07-25
> 18:02:06|22101|117:117|image|OS.pm:is_ssh_responding(678)|vm0-34 is
> responding to SSH, port 22: open, port 24: closed
> 2014-07-25
> 18:02:06|22101|117:117|image|Module.pm:code_loop_timeout(900)|waiting for
> vm0-34 to respond to SSH, code returned true
> 2014-07-25
> 18:02:06|22101|117:117|image|utils.pm:run_ssh_command(4902)|executing
> SSH command on vm0-34:
> |22101|117:117|image| /usr/bin/ssh -i /etc/vcl/vcl.key -o
> StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o
> ConnectionAttempts=1 -o ConnectTimeout=3 -l root -p 22 -x vm0-34
> '/sbin/shutdown -h now' 2>&1
> 2014-07-25
> 18:02:06|22101|117:117|image|utils.pm:run_ssh_command(5020)|run_ssh_command
> output:
> 2014-07-25 18:02:06|22101|117:117|image|utils.pm:run_ssh_command(5034)|SSH
> command executed on vm0-34, returning (0, "")
> 2014-07-25
> 18:02:06|22101|117:117|image|Module.pm:code_loop_timeout(887)|waiting for
> vm0-34 to power off, maximum of 300 seconds
> 2014-07-25
> 18:02:06|22101|117:117|image|vSphere_SDK.pm:get_vm_power_state(475)|power
> state of VM [vmware_vms_1] vm0-34_2-v0/vm0-34_2-v0.vmx: on
> 2014-07-25
> 18:02:06|22101|117:117|image|Module.pm:code_loop_timeout(909)|attempt 1:
> waiting for vm0-34 to power off (0/300 elapsed/remaining seconds), sleeping
> for 15 seconds
> 2014-07-25
> 18:02:21|22101|117:117|image|vSphere_SDK.pm:get_vm_power_state(475)|power
> state of VM [vmware_vms_1] vm0-34_2-v0/vm0-34_2-v0.vmx: off
> 2014-07-25
> 18:02:21|22101|117:117|image|Module.pm:code_loop_timeout(900)|waiting for
> vm0-34 to power off, code returned true
> 2014-07-25
> 18:02:21|22101|117:117|image|Module.pm:code_loop_timeout(887)|waiting for
> vm0-34 to power off, maximum of 300 seconds
> 2014-07-25
> 18:02:21|22101|117:117|image|vSphere_SDK.pm:get_vm_power_state(475)|power
> state of VM [vmware_vms_1] vm0-34_2-v0/vm0-34_2-v0.vmx: off
> 2014-07-25
> 18:02:21|22101|117:117|image|Module.pm:code_loop_timeout(900)|waiting for
> vm0-34 to power off, code returned true
> 2014-07-25 18:02:21|22101|117:117|image|Linux.pm:pre_capture(208)|Linux
> pre-capture steps complete
> 2014-07-25
> 18:02:21|22101|117:117|image|Module.pm:code_loop_timeout(887)|waiting for
> vm0-34 to power off, maximum of 600 seconds
> 2014-07-25
> 18:02:21|22101|117:117|image|vSphere_SDK.pm:get_vm_power_state(475)|power
> state of VM [vmware_vms_1] vm0-34_2-v0/vm0-34_2-v0.vmx: off
> 2014-07-25
> 18:02:21|22101|117:117|image|Module.pm:code_loop_timeout(900)|waiting for
> vm0-34 to power off, code returned true
> 2014-07-25
> 18:02:21|22101|117:117|image|vSphere_SDK.pm:_get_file_info(2520)|searching
> for matching file paths: base directory path: '[vmware_vms_1] vm0-34_2-v0',
> search pattern: 'vmwarelinux-CentOS6464bit2-v0-000001.vmdk'
> 2014-07-25
> 18:02:23|22101|117:117|image|vSphere_SDK.pm:_get_file_info(2575)|retrieved
> info for 1 matching files:
> |22101|117:117|image| : {
> |22101|117:117|image| : "[vmware_vms_1]
> vm0-34_2-v0/vmwarelinux-CentOS6464bit2-v0-000001.vmdk" => bless( {
> |22101|117:117|image| : "capacityKb" => 16777216,
> |22101|117:117|image| : "diskExtents" => [
> |22101|117:117|image| : "[vmware_vms_1]
> vm0-34_2-v0/vmwarelinux-CentOS6464bit2-v0-000001-delta.vmdk"
> |22101|117:117|image| : ],
> |22101|117:117|image| : "diskType" =>
> "VirtualDiskSparseVer2BackingInfo",
> |22101|117:117|image| : "fileSize" => 34603008,
> |22101|117:117|image| : "hardwareVersion" => 0,
> |22101|117:117|image| : "modification" => "2014-07-23T19:26:57Z",
> |22101|117:117|image| : "owner" => "root",
> |22101|117:117|image| : "path" =>
> "vmwarelinux-CentOS6464bit2-v0-000001.vmdk",
> |22101|117:117|image| : "thin" => 0,
> |22101|117:117|image| : "type" => "VmDiskFileInfo"
> |22101|117:117|image| : }, 'VmDiskFileInfo' )
> |22101|117:117|image| : }
> 2014-07-25
> 18:02:23|22101|117:117|image|vSphere_SDK.pm:find_files(2120)|matching file
> count: 2
> 2014-07-25
> 18:02:23|22101|117:117|image|vSphere_SDK.pm:file_exists(1988)|file exists:
> [vmware_vms_1] vm0-34_2-v0/vmwarelinux-CentOS6464bit2-v0-000001.vmdk
> 2014-07-25
> 18:02:23|22101|117:117|image|vSphere_SDK.pm:_get_file_info(2520)|searching
> for matching file paths: base directory path: '[vmware_images_1]
> vmwarelinux-CentOS6464bit2-v1', search pattern:
> 'vmwarelinux-CentOS6464bit2-v1.vmdk'
> 2014-07-25
> 18:02:25|22101|117:117|image|vSphere_SDK.pm:_get_file_info(2531)|base
> directory does not exist: '[vmware_images_1] vmwarelinux-CentOS6464bit2-v1'
> 2014-07-25
> 18:02:25|22101|117:117|image|vSphere_SDK.pm:find_files(2120)|matching file
> count: 0
> 2014-07-25
> 18:02:25|22101|117:117|image|vSphere_SDK.pm:file_exists(1992)|file does not
> exist: [vmware_images_1]
> vmwarelinux-CentOS6464bit2-v1/vmwarelinux-CentOS6464bit2-v1.vmdk
> 2014-07-25
> 18:02:25|22101|117:117|image|vSphere_SDK.pm:_get_file_info(2520)|searching
> for matching file paths: base directory path: '[vmware_vms_1] vm0-34_2-v0',
> search pattern: 'vmwarelinux-CentOS6464bit2-v0-000001.vmdk'
> 2014-07-25
> 18:02:27|22101|117:117|image|vSphere_SDK.pm:_get_file_info(2575)|retrieved
> info for 1 matching files:
> |22101|117:117|image| : {
> |22101|117:117|image| : "[vmware_vms_1]
> vm0-34_2-v0/vmwarelinux-CentOS6464bit2-v0-000001.vmdk" => bless( {
> |22101|117:117|image| : "capacityKb" => 16777216,
> |22101|117:117|image| : "diskExtents" => [
> |22101|117:117|image| : "[vmware_vms_1]
> vm0-34_2-v0/vmwarelinux-CentOS6464bit2-v0-000001-delta.vmdk"
> |22101|117:117|image| : ],
> |22101|117:117|image| : "diskType" =>
> "VirtualDiskSparseVer2BackingInfo",
> |22101|117:117|image| : "fileSize" => 34603008,
> |22101|117:117|image| : "hardwareVersion" => 0,
> |22101|117:117|image| : "modification" => "2014-07-23T19:26:57Z",
> |22101|117:117|image| : "owner" => "root",
> |22101|117:117|image| : "path" =>
> "vmwarelinux-CentOS6464bit2-v0-000001.vmdk",
> |22101|117:117|image| : "thin" => 0,
> |22101|117:117|image| : "type" => "VmDiskFileInfo"
> |22101|117:117|image| : }, 'VmDiskFileInfo' )
> |22101|117:117|image| : }
> 2014-07-25
> 18:02:27|22101|117:117|image|vSphere_SDK.pm:_get_file_info(2520)|searching
> for matching file paths: base directory path: '[vmware_images_1]', search
> pattern: 'vmwarelinux-CentOS6464bit2-v1'
> 2014-07-25
> 18:02:29|22101|117:117|image|vSphere_SDK.pm:_get_file_info(2575)|retrieved
> info for 0 matching files:
> |22101|117:117|image| : {}
> 2014-07-25
> 18:02:29|22101|117:117|image|vSphere_SDK.pm:find_files(2120)|matching file
> count: 0
> 2014-07-25
> 18:02:29|22101|117:117|image|vSphere_SDK.pm:file_exists(1992)|file does not
> exist: [vmware_images_1] vmwarelinux-CentOS6464bit2-v1
> 2014-07-25
> 18:02:29|22101|117:117|image|vSphere_SDK.pm:create_directory(1546)|created
> directory: '[vmware_images_1] vmwarelinux-CentOS6464bit2-v1'
> 2014-07-25
> 18:02:29|22101|117:117|image|vSphere_SDK.pm:copy_virtual_disk(685)|attempting
> to copy virtual disk on VM host vcl-vcenter-1: '[vmware_vms_1]
> vm0-34_2-v0/vmwarelinux-CentOS6464bit2-v0-000001.vmdk' -->
> '[vmware_images_1]
> vmwarelinux-CentOS6464bit2-v1/vmwarelinux-CentOS6464bit2-v1.vmdk'
> |22101|117:117|image| source adapter type: lsiLogic
> |22101|117:117|image| destination adapter type: lsiLogic
> |22101|117:117|image| disk type: VirtualDiskSparseVer2BackingInfo
> |22101|117:117|image| source capacity: 17,179,869,184 bytes - 16,777,216.0
> KB - 16,384.0 MB - 16.00 GB
> |22101|117:117|image| source space used: 34,603,008 bytes - 33,792.0 KB -
> 33.0 MB - 0.03 GB
> 2014-07-25
> 18:02:31|22101|117:117|image|vSphere_SDK.pm:copy_virtual_disk(726)|unable
> to copy vmdk using CopyVirtualDisk function, VM host vcl-vcenter-1 does not
> implement the CopyVirtualDisk function
> 2014-07-25
> 18:02:31|22101|117:117|image|vSphere_SDK.pm:delete_file(1596)|attempting to
> delete file: [vmware_images_1] vmwarelinux-CentOS6464bit2-v1
> 2014-07-25
> 18:02:33|22101|117:117|image|vSphere_SDK.pm:delete_file(1609)|deleted file:
> [vmware_images_1] vmwarelinux-CentOS6464bit2-v1
> 2014-07-25
> 18:02:33|22101|117:117|image|vSphere_SDK.pm:_clean_vm_name(503)|truncating
> VM name source_vmwarelinux-CentOS6464bit2-v1
> 2014-07-25 18:02:33|22101|117:117|image|utils.pm:get_image_info(4342)|image
> does NOT exist in the database: source_vmwarelinux-CentOS2-v
> 2014-07-25
> 18:02:33|22101|117:117|image|vSphere_SDK.pm:_clean_vm_name(522)|Changed
> image name to: source_vmwarelinux-CentOS2-v1
> 2014-07-25
> 18:02:34|22101|117:117|image|vSphere_SDK.pm:_get_file_info(2520)|searching
> for matching file paths: base directory path: '[vmware_vms_1]', search
> pattern: 'source_vmwarelinux-CentOS2-v1'
> 2014-07-25
> 18:02:36|22101|117:117|image|vSphere_SDK.pm:_get_file_info(2575)|retrieved
> info for 0 matching files:
> |22101|117:117|image| : {}
> 2014-07-25
> 18:02:36|22101|117:117|image|vSphere_SDK.pm:find_files(2120)|matching file
> count: 0
> 2014-07-25
> 18:02:36|22101|117:117|image|vSphere_SDK.pm:file_exists(1992)|file does not
> exist: [vmware_vms_1] source_vmwarelinux-CentOS2-v1
> 2014-07-25
> 18:02:36|22101|117:117|image|vSphere_SDK.pm:_get_file_info(2520)|searching
> for matching file paths: base directory path: '[vmware_images_1]', search
> pattern: 'vmwarelinux-CentOS6464bit2-v1'
> 2014-07-25
> 18:02:38|22101|117:117|image|vSphere_SDK.pm:_get_file_info(2575)|retrieved
> info for 0 matching files:
> |22101|117:117|image| : {}
> 2014-07-25
> 18:02:38|22101|117:117|image|vSphere_SDK.pm:find_files(2120)|matching file
> count: 0
> 2014-07-25
> 18:02:38|22101|117:117|image|vSphere_SDK.pm:file_exists(1992)|file does not
> exist: [vmware_images_1] vmwarelinux-CentOS6464bit2-v1
> 2014-07-25
> 18:02:38|22101|117:117|image|vSphere_SDK.pm:copy_virtual_disk(853)|attempting
> to copy virtual disk by cloning temporary VM: '[vmware_vms_1]
> vm0-34_2-v0/vmwarelinux-CentOS6464bit2-v0-000001.vmdk' -->
> '[vmware_images_1]
> vmwarelinux-CentOS6464bit2-v1/vmwarelinux-CentOS6464bit2-v1.vmdk'
> |22101|117:117|image| adapter type: lsiLogic
> |22101|117:117|image| source disk type: VirtualDiskSparseVer2BackingInfo
> |22101|117:117|image| source capacity: 17,179,869,184 bytes - 16,777,216.0
> KB - 16,384.0 MB - 16.00 GB
> |22101|117:117|image| source space used: 34,603,008 bytes - 33,792.0 KB -
> 33.0 MB - 0.03 GB
> |22101|117:117|image| source VM name: source_vmwarelinux-CentOS2-v1
> |22101|117:117|image| clone VM name: vmwarelinux-CentOS6464bit2-v1
> |22101|117:117|image| source VM directory path: [vmware_vms_1]
> source_vmwarelinux-CentOS2-v1
> |22101|117:117|image| clone VM directory path: [vmware_images_1]
> vmwarelinux-CentOS6464bit2-v1
> 2014-07-25 18:04:14|22101|117:117|image|vSphere_SDK.pm:(eval)(873)|created
> temporary source VM which will be cloned: source_vmwarelinux-CentOS2-v1
> 2014-07-25 18:04:14|22101|117:117|image|vSphere_SDK.pm:(eval)(881)|cloning
> VM: source_vmwarelinux-CentOS2-v1 --> vmwarelinux-CentOS6464bit2-v1
> |22101|117:117|image| ---- WARNING ----
> |22101|117:117|image| 2014-07-25
> 18:18:03|22101|117:117|image|vSphere_SDK.pm:copy_virtual_disk(908)|failed
> to copy vmdk on VM host vcl-vcenter-1: '[vmware_vms_1]
> vm0-34_2-v0/vmwarelinux-CentOS6464bit2-v0-000001.vmdk' -->
> '[vmware_images_1]
> vmwarelinux-CentOS6464bit2-v1/vmwarelinux-CentOS6464bit2-v1.vmdk'
> |22101|117:117|image| error:
> |22101|117:117|image| SOAP Fault:
> |22101|117:117|image| -----------
> |22101|117:117|image| Fault string: Error caused by file [vmware_vms_1]
> vm0-34_2-v0/vmwarelinux-CentOS6464bit2-v0-000001.vmdk
> |22101|117:117|image| Fault detail: FileFault
> |22101|117:117|image| ( 0) vSphere_SDK.pm, copy_virtual_disk (line: 908)
> |22101|117:117|image| (-1) VMware.pm, copy_vmdk (line: 5824)
> |22101|117:117|image| (-2) VMware.pm, capture (line: 744)
> |22101|117:117|image| (-3) image.pm, process (line: 162)
> |22101|117:117|image| (-4) vcld, make_new_child (line: 571)
> |22101|117:117|image| (-5) vcld, main (line: 350)
> |22101|117:117|image| ---- WARNING ----
> |22101|117:117|image| 2014-07-25
> 18:18:03|22101|117:117|image|VMware.pm:copy_vmdk(5840)|failed to copy vmdk
> using API's copy_virtual_disk subroutine
> |22101|117:117|image| ( 0) VMware.pm, copy_vmdk (line: 5840)
> |22101|117:117|image| (-1) VMware.pm, capture (line: 744)
> |22101|117:117|image| (-2) image.pm, process (line: 162)
> |22101|117:117|image| (-3) vcld, make_new_child (line: 571)
> |22101|117:117|image| (-4) vcld, main (line: 350)
> |22101|117:117|image| ---- WARNING ----
> |22101|117:117|image| 2014-07-25
> 18:18:03|22101|117:117|image|VMware.pm:capture(745)|failed to copy the vmdk
> files after the VM was powered off:
> '/vmfs/volumes/vmware_vms_1/vm0-34_2-v0/vmwarelinux-CentOS6464bit2-v0-000001.vmdk'
> -->
> '/vmfs/volumes/vmware_images_1/vmwarelinux-CentOS6464bit2-v1/vmwarelinux-CentOS6464bit2-v1.vmdk'
> |22101|117:117|image| ( 0) VMware.pm, capture (line: 745)
> |22101|117:117|image| (-1) image.pm, process (line: 162)
> |22101|117:117|image| (-2) vcld, make_new_child (line: 571)
> |22101|117:117|image| (-3) vcld, main (line: 350)
> |22101|117:117|image| ---- WARNING ----
> |22101|117:117|image| 2014-07-25
> 18:18:03|22101|117:117|image|image.pm:process(166)|vmwarelinux-CentOS6464bit2-v1
> image failed to be captured by provisioning module
> |22101|117:117|image| ( 0) image.pm, process (line: 166)
> |22101|117:117|image| (-1) vcld, make_new_child (line: 571)
> |22101|117:117|image| (-2) vcld, main (line: 350)
> 2014-07-25
> 18:18:03|22101|117:117|image|utils.pm:get_management_node_info(5456)|retrieving
> current management node info for 'vcl-mgmtnode-1' from database, cached
> data is stale: 993 seconds old
> 2014-07-25
> 18:18:03|22101|117:117|image|utils.pm:get_management_node_info(5603)|retrieved
> management node info: 'vcl-mgmtnode-1' (vcl-mgmtnode-1)
> |22101|117:117|image| ---- CRITICAL ----
> |22101|117:117|image| 2014-07-25
> 18:18:03|22101|117:117|image|image.pm:reservation_failed(387)|vmwarelinux-CentOS6464bit2-v1
> image creation failed
> |22101|117:117|image| ( 0) image.pm, reservation_failed (line: 387)
> |22101|117:117|image| (-1) image.pm, process (line: 167)
> |22101|117:117|image| (-2) vcld, make_new_child (line: 571)
> |22101|117:117|image| (-3) vcld, main (line: 350)
> 2014-07-25 18:18:04|22101|117:117|image|utils.pm:mail(1266)|SUCCESS --
> Sending mail To: [email protected], VCL -- NOTICE DELAY Image
> Creation CentOS 6.4 Base
> 2014-07-25
> 18:18:04|22101|117:117|image|utils.pm:update_request_state(1545)|request
> 117 state updated to: maintenance, laststate to: image
> 2014-07-25
> 18:18:04|22101|117:117|image|image.pm:reservation_failed(441)|request
> state set to maintenance, laststate to image
> 2014-07-25
> 18:18:04|22101|117:117|image|utils.pm:update_computer_state(1587)|computer
> 26 state updated to: maintenance
> 2014-07-25
> 18:18:04|22101|117:117|image|image.pm:reservation_failed(449)|vm0-34
> state set to maintenance
> 2014-07-25 18:18:04|22101|117:117|image|image.pm:
> reservation_failed(456)|exiting
> 2014-07-25
> 18:18:04|22101|117:117|image|utils.pm:delete_computerloadlog_reservation(6396)|removing
> computerloadlog entries matching loadstate = begin
> 2014-07-25
> 18:18:04|22101|117:117|image|utils.pm:delete_computerloadlog_reservation(6443)|deleted
> rows from computerloadlog for reservation id=117
> 2014-07-25 18:18:04|22101|117:117|image|State.pm:DESTROY(929)|VCL::image
> process duration: 1000 seconds
>
>
> On Fri, Jul 25, 2014 at 10:03 AM, Andy Kurth <[email protected]> wrote:
>
>> The root problem seems to be a mismatch of the private IP address for the
>> management node defined in /etc/hosts (136.159.222.142) and the address
>> actually being used on the management node (136.159.222.191). This caused
>> a problem when the firewall was initially configured for the reservation
>> due to some poorly written firewall code which locked the management node
>> out of the VM. The image capture is failing because the management node is
>> not able to log in to the VM via SSH due to the firewall.
>>
>> To fix the problem, first check /etc/hosts on the management node and
>> make sure the entry for vcl-mgmtnode-1 matches what the management node is
>> actually using.
>>
>> You will then need to log in to the VM and fix iptables so the management
>> node can log in on port 22. The VM's root password was randomized but you
>> can find it in the vcld.log output by searching for 'passwd'.
>>
>> Verify that you can log in via SSH from the management node to the VM and
>> then reattempt the image capture by changing the value in the database's
>> request table. Find request ID = 117, change request.stateid from 10 to
>> 16.
>>
>> Regards,
>> Andy
>>
>>
>>
>> On Wed, Jul 23, 2014 at 6:17 PM, Xiaowei Liu (Vivien) <
>> [email protected]> wrote:
>>
>>> Hi Aaron,
>>>
>>> I collected the related logs with request and reservation id 117:117,
>>> and attached the log with the email. I searched for "failed" keyword, and
>>> there are several places that have different errors.
>>>
>>> Could you please advice some next step to try in order to solve our
>>> issue?
>>>
>>> Thanks a lot for your prompt reply.
>>>
>>>
>>>
>>> On Wed, Jul 23, 2014 at 2:22 PM, Aaron Peeler <[email protected]>
>>> wrote:
>>>
>>>> You will need to find the request id that relates to the failed
>>>> reservation.
>>>>
>>>> In the logfile you will see the format string of:
>>>> <data_time>|pid from OS|requestid:reservationid|<state>|.......
>>>>
>>>> You can grep for the state image.
>>>>
>>>> or
>>>>
>>>> The you can find out the requestid from the mysql db.
>>>>
>>>> Go to the database and using phpmyadmin or cmdline, or which ever db
>>>> management tool you use and look in the request table for any
>>>> reservations in with stateid=16 which is the maintenance state.
>>>>
>>>> Once you have the request.id you can narrow down the log file to trace
>>>> through the part where it failed.
>>>>
>>>> The log output you sent only contains reservations in the inuse state.
>>>>
>>>> Aaron
>>>>
>>>>
>>>> On Wed, Jul 23, 2014 at 3:59 PM, Xiaowei Liu (Vivien)
>>>> <[email protected]> wrote:
>>>> > Hi Aaron,
>>>> >
>>>> > Yes. I have the administrator access to VCL system.
>>>> >
>>>> > I look at the /var/log/vcld.log and there are lots of content in it,
>>>> not
>>>> > sure which keywords I should search for. Could you please hint some
>>>> keywords
>>>> > related to updating an existing base image?
>>>> >
>>>> >
>>>> > On Wed, Jul 23, 2014 at 1:36 PM, Aaron Peeler <[email protected]>
>>>> wrote:
>>>> >>
>>>> >> Hello,
>>>> >>
>>>> >> You'll need to look at the /var/log/vcld.log file for the details of
>>>> >> why it failed.
>>>> >>
>>>> >> Do you have access to the log file on the vcl management node? Are
>>>> you
>>>> >> the VCL administrator for that system? Sorry, that's not clear from
>>>> >> your email.
>>>> >>
>>>> >> Thanks,
>>>> >> Aaron
>>>> >>
>>>> >>
>>>> >> On Wed, Jul 23, 2014 at 2:04 PM, Xiaowei Liu (Vivien)
>>>> >> <[email protected]> wrote:
>>>> >> > Hi,
>>>> >> >
>>>> >> > We are following this wiki page
>>>> >> >
>>>> >> >
>>>> https://cwiki.apache.org/confluence/display/VCL/Updating+an+Existing+Image
>>>> >> > to try to update an existing base image in our VCL system. But
>>>> when we
>>>> >> > try
>>>> >> > to save the image, the user kept getting the following email and
>>>> the
>>>> >> > process
>>>> >> > doesn't seem to work.
>>>> >> >
>>>> >> > Could someone please kindly advice what should we do about it?
>>>> Does the
>>>> >> > administrator need to configure something manually to make it
>>>> happen?
>>>> >> > Thanks
>>>> >> > a lot!
>>>> >> >
>>>> >> > The email notification has the following content:
>>>> >> >
>>>> >> > "We apologize for the inconvenience.
>>>> >> > Your image creation of av2014_testbase has been delayed
>>>> >> > due to a system issue that prevented the automatic completion.
>>>> >> >
>>>> >> > The image creation request and the computing resource have
>>>> >> > been placed in a safe mode. The VCL system administrators
>>>> >> > have been notified for manual intervention.
>>>> >> >
>>>> >> > Once the issues have been resolved, you will be notified
>>>> >> > by the successful completion email or contacted directly
>>>> >> > by the VCL system administrators.
>>>> >> >
>>>> >> > If you do not receive a response within one business day, please
>>>> >> > reply to this email.
>>>> >> >
>>>> >> > Thank You,
>>>> >> > VCL Team"
>>>> >>
>>>> >>
>>>> >>
>>>> >> --
>>>> >> 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.
>>>> >
>>>> >
>>>>
>>>>
>>>>
>>>> --
>>>> 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.
>>>>
>>>
>>>
>>
>
