Hi António, Please see the thread: http://vcl.markmail.org/thread/v6yyheycyucsdsn3
I had issues after an ESXi upgrade disabled the 2GB sparse format, and had this bookmarked having experienced similar issues creating an image via VCL. The other issue to check (also from this thread) would be permissions. Also confirm that the repository paths in your VCL config correspond with the real paths on the ESXi host, although skimming your log output I believe this is okay. Regards, Mike On Wed, Sep 23, 2015 at 10:30 AM, António Aragão <[email protected]> wrote: > Hi, > > I was trying to create a new image and now it gives me an error. Any clues > ? I have lot of space in both: > > ~ # df -h > Filesystem Size Used Available Use% Mounted on > NFS 150.0G 133.7G 16.3G 89% /vmfs/volumes/nas:isos > NFS 3.1T 2.3T 749.5G 76% /vmfs/volumes/nas:vm-backups > NFS 983.2G 211.6G 771.6G 22% /vmfs/volumes/vcl_images > VMFS-5 4.3T 2.3T 2.0T 54% /vmfs/volumes/datastore1 > vfat 4.0G 25.9M 4.0G 1% > /vmfs/volumes/52d422c0-c505318e-9038-0025905aa03c > vfat 249.7M 157.0M 92.7M 63% > /vmfs/volumes/fd17657e-443d0989-0ad6-8fe725643b5d > vfat 249.7M 8.0K 249.7M 0% > /vmfs/volumes/2d1a7278-096eb83e-bf00-f727d3ce63da > vfat 285.8M 191.3M 94.6M 67% > /vmfs/volumes/52d42299-a598680f-7d85-0025905aa03c > > It complains about cloning. > > Thanks. > > > ---------- Forwarded message ---------- > From: <[email protected]> > Date: 2015-09-23 15:10 GMT+01:00 > Subject: PROBLEM -- vclnode1|263:263|image|image.pm|vm18> > servidor12.di.uminho.pt|vmwarewin7-WIN7_20150923_VMWARE_0000191-v0|admin > To: [email protected] > > > vmwarewin7-WIN7_20150923_VMWARE_0000191-v0 image creation failed > ------------------------------------------------------------------------ > time: 2015-09-23 15:09:50 > caller: image.pm:reservation_failed(387) > ( 0) image.pm, reservation_failed (line: 387) > (-1) image.pm, process (line: 167) > (-2) vcld, make_new_child (line: 571) > (-3) vcld, main (line: 350) > ------------------------------------------------------------------------ > management node: vclnode1.apachevcl.di.uminho.pt > reservation PID: 22474 > parent vcld PID: 1826 > > request ID: 263 > reservation ID: 263 > request state/laststate: image/reserved > request start time: 2015-09-23 13:15:00 > request end time: 2015-09-23 21:30:00 > for imaging: yes > log ID: 227 > > computer: vm18.apachevcl.di.uminho.pt > computer id: 22 > computer type: virtualmachine > computer eth0 MAC address: 00:50:56:00:00:22 > computer eth1 MAC address: 00:50:56:00:00:23 > computer private IP address: 10.100.0.118 > computer public IP address: 192.168.93.118 > computer in block allocation: no > provisioning module: VCL::Module::Provisioning::VMware::VMware > > vm host: servidor12.di.uminho.pt > vm host ID: 1 > vm host computer ID: 1 > vm profile: vmhostprofile1 > vm profile VM path: /vmfs/volumes/datastore1/ > vm profile repository path: /vmfs/volumes/vcl_images/ > vm profile datastore path: /vmfs/volumes/datastore1/ > vm profile disk type: shared > > image: vmwarewin7-WIN7_20150923_VMWARE_0000191-v0 > image display name: WIN7_20150923_VMWARE_00001 > image ID: 91 > image revision ID: 88 > image size: 1450 MB > use Sysprep: no > root access: yes > image owner ID: 1 > image owner affiliation: Local > image revision date created: 2015-09-23 13:33:27 > image revision production: yes > OS module: VCL::Module::OS::Windows::Version_6::7 > > user: admin > user name: vcl admin > user ID: 1 > user affiliation: Local > ------------------------------------------------------------------------ > RECENT LOG ENTRIES FOR THIS PROCESS: > |22474|263:263|image| returning (1, "stat: can't stat '/vmfs/volume...") > 2015-09-23 > 15:09:07|22474|263:263|image|utils.pm:run_ssh_command(4902)|executing > SSH command on servidor12: > |22474|263:263|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 servidor12 'ls -d > --color=never > "/vmfs/volumes/vcl_images/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0" 2>&1 > || mkdir -p > "/vmfs/volumes/vcl_images/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0" 2>&1 > && ls -d --color=never > "/vmfs/volumes/vcl_images/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0"' 2>&1 > 2015-09-23 > 15:09:07|22474|263:263|image|utils.pm:run_ssh_command(5020)|run_ssh_command > output: > |22474|263:263|image| ls: > /vmfs/volumes/vcl_images/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0: No > such file or directory > |22474|263:263|image| > /vmfs/volumes/vcl_images/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0 > 2015-09-23 15:09:07|22474|263:263|image|utils.pm:run_ssh_command(5034)|SSH > command executed on servidor12, returning (0, "ls: > /vmfs/volumes/vcl_images/v...") > 2015-09-23 > 15:09:07|22474|263:263|image|Linux.pm:create_directory(1569)|directory > created on servidor12: > '/vmfs/volumes/vcl_images/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0' > 2015-09-23 > 15:09:07|22474|263:263|image|VMware.pm:copy_vmdk(5861)|attempting to copy > virtual disk using vmkfstools, disk type: 2gbsparse: > |22474|263:263|image| > '/vmfs/volumes/datastore1/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0.vmdk' > --> > '/vmfs/volumes/vcl_images/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0.vmdk' > 2015-09-23 > 15:09:08|22474|263:263|image|utils.pm:run_ssh_command(4902)|executing > SSH command on servidor12: > |22474|263:263|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 servidor12 > 'vmkfstools -i > "/vmfs/volumes/datastore1/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0.vmdk" > "/vmfs/volumes/vcl_images/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0.vmdk" > -d 2gbsparse' 2>&1 > 2015-09-23 15:09:33|22474|263:263|image|OS.pm:execute(1994)|executed > command: 'vmkfstools -i > "/vmfs/volumes/datastore1/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0.vmdk" > "/vmfs/volumes/vcl_images/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0.vmdk" > -d 2gbsparse', exit status: 255, output: > |22474|263:263|image| Failed to clone disk: The system cannot find the > file specified (25). > |22474|263:263|image| Destination disk format: sparse with 2GB maximum > extent size > |22474|263:263|image| Cloning disk > '/vmfs/volumes/datastore1/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0.vmdk'... > |22474|263:263|image| ---- WARNING ---- > |22474|263:263|image| 2015-09-23 > 15:09:33|22474|263:263|image|VMware.pm:copy_vmdk(5865)|failed to copy > virtual disk > |22474|263:263|image| command: 'vmkfstools -i > "/vmfs/volumes/datastore1/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0.vmdk" > "/vmfs/volumes/vcl_images/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0.vmdk" > -d 2gbsparse' > |22474|263:263|image| output: > |22474|263:263|image| Failed to clone disk: The system cannot find the > file specified (25). > |22474|263:263|image| Destination disk format: sparse with 2GB maximum > extent size > |22474|263:263|image| Cloning disk > '/vmfs/volumes/datastore1/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0.vmdk'... > |22474|263:263|image| ( 0) VMware.pm, copy_vmdk (line: 5865) > |22474|263:263|image| (-1) VMware.pm, capture (line: 774) > |22474|263:263|image| (-2) image.pm, process (line: 162) > |22474|263:263|image| (-3) vcld, make_new_child (line: 571) > |22474|263:263|image| (-4) vcld, main (line: 350) > 2015-09-23 > 15:09:33|22474|263:263|image|VMware.pm:copy_vmdk(5918)|attempting to copy > virtual disk using vmware-vdiskmanager, disk type: 2gbsparse: > |22474|263:263|image| > '/vmfs/volumes/datastore1/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0.vmdk' > --> > '/vmfs/volumes/vcl_images/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0.vmdk' > 2015-09-23 > 15:09:33|22474|263:263|image|utils.pm:run_ssh_command(4902)|executing > SSH command on servidor12: > |22474|263:263|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 servidor12 > 'vmware-vdiskmanager -r > "/vmfs/volumes/datastore1/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0.vmdk" > -t 1 > "/vmfs/volumes/vcl_images/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0.vmdk"' > 2>&1 > 2015-09-23 15:09:33|22474|263:263|image|OS.pm:execute(1994)|executed > command: 'vmware-vdiskmanager -r > "/vmfs/volumes/datastore1/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0.vmdk" > -t 1 > "/vmfs/volumes/vcl_images/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0.vmdk"', > exit status: 127, output: > |22474|263:263|image| sh: vmware-vdiskmanager: not found > |22474|263:263|image| ---- WARNING ---- > |22474|263:263|image| 2015-09-23 > 15:09:33|22474|263:263|image|VMware.pm:copy_vmdk(5990)|failed to copy > virtual disk on VM host servidor12, output does not contain '100% done' or > 'success', command: 'vmware-vdiskmanager -r > "/vmfs/volumes/datastore1/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0.vmdk" > -t 1 > "/vmfs/volumes/vcl_images/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0.vmdk"', > output: > |22474|263:263|image| sh: vmware-vdiskmanager: not found > |22474|263:263|image| ( 0) VMware.pm, copy_vmdk (line: 5990) > |22474|263:263|image| (-1) VMware.pm, capture (line: 774) > |22474|263:263|image| (-2) image.pm, process (line: 162) > |22474|263:263|image| (-3) vcld, make_new_child (line: 571) > |22474|263:263|image| (-4) vcld, main (line: 350) > |22474|263:263|image| ---- WARNING ---- > |22474|263:263|image| 2015-09-23 > 15:09:33|22474|263:263|image|VMware.pm:copy_vmdk(6055)|failed to copy > virtual disk on VM host servidor12 using any available methods: > |22474|263:263|image| > '/vmfs/volumes/datastore1/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0.vmdk' > --> > '/vmfs/volumes/vcl_images/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0.vmdk' > |22474|263:263|image| ( 0) VMware.pm, copy_vmdk (line: 6055) > |22474|263:263|image| (-1) VMware.pm, capture (line: 774) > |22474|263:263|image| (-2) image.pm, process (line: 162) > |22474|263:263|image| (-3) vcld, make_new_child (line: 571) > |22474|263:263|image| (-4) vcld, main (line: 350) > 2015-09-23 > 15:09:33|22474|263:263|image|utils.pm:run_ssh_command(4902)|executing > SSH command on servidor12: > |22474|263:263|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 servidor12 'rm > -rfv /vmfs/volumes/vcl_images/vmwarewin7\-WIN7_20150923_VMWARE_0000191\-v0' > 2>&1 > 2015-09-23 > 15:09:33|22474|263:263|image|utils.pm:run_ssh_command(5020)|run_ssh_command > output: > 2015-09-23 15:09:33|22474|263:263|image|utils.pm:run_ssh_command(5034)|SSH > command executed on servidor12, returning (0, "") > 2015-09-23 15:09:33|22474|263:263|image|Linux.pm:delete_file(1504)|deleted > '/vmfs/volumes/vcl_images/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0' on > servidor12 > 2015-09-23 > 15:09:33|22474|263:263|image|utils.pm:run_ssh_command(4902)|executing > SSH command on servidor12: > |22474|263:263|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 servidor12 'stat > /vmfs/volumes/vcl_images/vmwarewin7\-WIN7_20150923_VMWARE_0000191\-v0' 2>&1 > 2015-09-23 > 15:09:34|22474|263:263|image|utils.pm:run_ssh_command(5020)|run_ssh_command > output: > |22474|263:263|image| stat: can't stat > '/vmfs/volumes/vcl_images/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0': No > such file or directory > 2015-09-23 15:09:34|22474|263:263|image|utils.pm:run_ssh_command(5030)|SSH > command executed on servidor12, command: > |22474|263:263|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 servidor12 'stat > /vmfs/volumes/vcl_images/vmwarewin7\-WIN7_20150923_VMWARE_0000191\-v0' 2>&1 > |22474|263:263|image| returning (1, "stat: can't stat '/vmfs/volume...") > |22474|263:263|image| ---- WARNING ---- > |22474|263:263|image| 2015-09-23 > 15:09:34|22474|263:263|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/datastore1/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0.vmdk' > --> > '/vmfs/volumes/vcl_images/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0.vmdk' > |22474|263:263|image| ( 0) VMware.pm, capture (line: 778) > |22474|263:263|image| (-1) image.pm, process (line: 162) > |22474|263:263|image| (-2) vcld, make_new_child (line: 571) > |22474|263:263|image| (-3) vcld, main (line: 350) > 2015-09-23 15:09:34|22474|263:263|image|VMware.pm:capture(870)|attempting > to delete directory where moved vmdk resided before reverting the name back > to the original: > /vmfs/volumes/datastore1/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0 > 2015-09-23 > 15:09:34|22474|263:263|image|utils.pm:run_ssh_command(4902)|executing > SSH command on servidor12: > |22474|263:263|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 servidor12 'rm > -rfv /vmfs/volumes/datastore1/vmwarewin7\-WIN7_20150923_VMWARE_0000191\-v0' > 2>&1 > 2015-09-23 > 15:09:35|22474|263:263|image|utils.pm:run_ssh_command(5020)|run_ssh_command > output: > 2015-09-23 15:09:35|22474|263:263|image|utils.pm:run_ssh_command(5034)|SSH > command executed on servidor12, returning (0, "") > 2015-09-23 15:09:35|22474|263:263|image|Linux.pm:delete_file(1504)|deleted > '/vmfs/volumes/datastore1/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0' on > servidor12 > 2015-09-23 > 15:09:35|22474|263:263|image|utils.pm:run_ssh_command(4902)|executing > SSH command on servidor12: > |22474|263:263|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 servidor12 'stat > /vmfs/volumes/datastore1/vmwarewin7\-WIN7_20150923_VMWARE_0000191\-v0' 2>&1 > 2015-09-23 > 15:09:36|22474|263:263|image|utils.pm:run_ssh_command(5020)|run_ssh_command > output: > |22474|263:263|image| stat: can't stat > '/vmfs/volumes/datastore1/vmwarewin7-WIN7_20150923_VMWARE_0000191-v0': No > such file or directory > 2015-09-23 15:09:36|22474|263:263|image|utils.pm:run_ssh_command(5030)|SSH > command executed on servidor12, command: > |22474|263:263|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 servidor12 'stat > /vmfs/volumes/datastore1/vmwarewin7\-WIN7_20150923_VMWARE_0000191\-v0' 2>&1 > |22474|263:263|image| returning (1, "stat: can't stat '/vmfs/volume...") > 2015-09-23 15:09:36|22474|263:263|image|VMware.pm:capture(876)|attempting > to power the VM back on so that it can be captured again > 2015-09-23 > 15:09:37|22474|263:263|image|VIM_SSH.pm:_run_vim_cmd(210)|executed command > on VM host servidor12: vim-cmd vmsvc/getallvms > 2015-09-23 > 15:09:45|22474|263:263|image|VIM_SSH.pm:_run_vim_cmd(210)|executed command > on VM host servidor12: vim-cmd vmsvc/power.on 311 > 2015-09-23 > 15:09:46|22474|263:263|image|VIM_SSH.pm:_run_vim_cmd(210)|executed command > on VM host servidor12: vim-cmd vmsvc/getallvms > 2015-09-23 > 15:09:48|22474|263:263|image|VIM_SSH.pm:_run_vim_cmd(210)|executed command > on VM host servidor12: vim-cmd vmsvc/get.tasklist 311 > 2015-09-23 > 15:09:48|22474|263:263|image|VIM_SSH.pm:_wait_for_task(750)|checking status > of task: haTask-311-vim.VirtualMachine.powerOn-187793592 > 2015-09-23 > 15:09:50|22474|263:263|image|VIM_SSH.pm:_run_vim_cmd(210)|executed command > on VM host servidor12: vim-cmd vimsvc/task_info > haTask-311-vim.VirtualMachine.powerOn-187793592 > 2015-09-23 > 15:09:50|22474|263:263|image|VIM_SSH.pm:_wait_for_task(773)|task completed > successfully: haTask-311-vim.VirtualMachine.powerOn-187793592 > 2015-09-23 > 15:09:50|22474|263:263|image|VIM_SSH.pm:vm_power_on(972)|powered on VM: > /vmfs/volumes/datastore1/vm18_67-v0/vm18_67-v0.vmx > |22474|263:263|image| ---- WARNING ---- > |22474|263:263|image| 2015-09-23 > 15:09:50|22474|263:263|image|image.pm:process(166)|vmwarewin7-WIN7_20150923_VMWARE_0000191-v0 > image failed to be captured by provisioning module > |22474|263:263|image| ( 0) image.pm, process (line: 166) > |22474|263:263|image| (-1) vcld, make_new_child (line: 571) > |22474|263:263|image| (-2) vcld, main (line: 350) > 2015-09-23 > 15:09:50|22474|263:263|image|DataStructure.pm:get_computer_private_ip_address(1617)|returning > private IP address previously retrieved: 10.100.0.118 > 2015-09-23 15:09:50|22474|263:263|image|utils.pm:is_inblockrequest(5760)|zero > rows were returned from database select > 2015-09-23 > 15:09:50|22474|263:263|image|DataStructure.pm:get_image_affiliation_name(2121)|image > owner id: 1 > 2015-09-23 > 15:09:50|22474|263:263|image|DataStructure.pm:retrieve_user_data(1412)|attempting > to retrieve and store data for user: user.id = '1' > 2015-09-23 > 15:09:50|22474|263:263|image|DataStructure.pm:retrieve_user_data(1475)|data > has been retrieved for user: admin (id: 1) > > > > -- > >
