Thanks Mike. For the windows 7 images the problem was the multiextent module.
Thanks. 2015-09-23 16:19 GMT+01:00 Mike Haudenschild <[email protected]>: > 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) >> >> >> >> -- >> >> > --
