You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@vcl.apache.org by António Aragão <aa...@di.uminho.pt> on 2015/09/23 16:30:01 UTC
Fwd: PROBLEM -- vclnode1|263:263|image|image.pm|vm18>servidor12.di.uminho.pt|vmwarewin7-WIN7_20150923_VMWARE_0000191-v0|admin
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: <ro...@vclnode1.apachevcl.di.uminho.pt>
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: aaragao@di.uminho.pt
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)
--
Re: PROBLEM -- vclnode1|263:263|image|image.pm|vm18>servidor12.di.uminho.pt|vmwarewin7-WIN7_20150923_VMWARE_0000191-v0|admin
Posted by António Aragão <aa...@di.uminho.pt>.
Thanks Mike.
For the windows 7 images the problem was the multiextent module.
Thanks.
2015-09-23 16:19 GMT+01:00 Mike Haudenschild <mh...@gmail.com>:
> 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 <aa...@di.uminho.pt>
> 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: <ro...@vclnode1.apachevcl.di.uminho.pt>
>> 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: aaragao@di.uminho.pt
>>
>>
>> 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)
>>
>>
>>
>> --
>>
>>
>
--
Re: PROBLEM -- vclnode1|263:263|image|image.pm|vm18>servidor12.di.uminho.pt|vmwarewin7-WIN7_20150923_VMWARE_0000191-v0|admin
Posted by Mike Haudenschild <mh...@gmail.com>.
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 <aa...@di.uminho.pt>
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: <ro...@vclnode1.apachevcl.di.uminho.pt>
> 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: aaragao@di.uminho.pt
>
>
> 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)
>
>
>
> --
>
>