Hi Andy, I see a bunch of "get_registered_vms" like the line below
|29339|116:116|reload| (-3) vSphere_SDK.pm, get_registered_vms (line: 208) |29339|116:116|reload| (-4) VMware.pm, get_vmx_file_paths (line: 5246) |29339|116:116|reload| (-5) VMware.pm, remove_existing_vms (line: 1556) |29339|116:116|reload| ---- WARNING ---- |29339|116:116|reload| 2014-04-03 11:22:24|29339|116:116|reload|VMware.pm:_get_datastore_root_normal_path(6916)|failed to determine datastore root normal path, unable to determine datastore name: [Old VM's] VSA FOM/VSA FOM.vmx |29339|116:116|reload| ( 0) VMware.pm, _get_datastore_root_normal_path (line: 6916) |29339|116:116|reload| (-1) VMware.pm, _get_normal_path (line: 7006) |29339|116:116|reload| (-2) vSphere_SDK.pm, get_registered_vms (line: 208) |29339|116:116|reload| (-3) VMware.pm, get_vmx_file_paths (line: 5246) in the client, I do see vcl-n-001:vmwarewin7...... and it's powered on still output from command: ~ # ps -c |grep '/bin/vmx .*vcl-n-001' 8239365 8239365 vmx /bin/vmx -s sched.group=host/user -# product=2;name=VMware ESX;version=5.5.0;buildnumber=1331820;licensename=VMware ESX Server;licenseversion=5.0; -@ duplex=3;msgs=ui /vmfs/volumes/5284a6b9-9d90bf28-a89e-d89d67260538/vcl-n-001_27-v7/vcl-n-001_27-v7.vmx 8239370 8239365 vmx-vthread-4:vcl-n-001:vmwarewin7-SocialScience27-v7 (shared) /bin/vmx -s sched.group=host/user -# product=2;name=VMware ESX;version=5.5.0;buildnumber=1331820;licensename=VMware ESX Server;licenseversion=5.0; -@ duplex=3;msgs=ui /vmfs/volumes/5284a6b9-9d90bf28-a89e-d89d67260538/vcl-n-001_27-v7/vcl-n-001_27-v7.vmx 8239371 8239365 vmx-mks:vcl-n-001:vmwarewin7-SocialScience27-v7 (shared) /bin/vmx -s sched.group=host/user -# product=2;name=VMware ESX;version=5.5.0;buildnumber=1331820;licensename=VMware ESX Server;licenseversion=5.0; -@ duplex=3;msgs=ui /vmfs/volumes/5284a6b9-9d90bf28-a89e-d89d67260538/vcl-n-001_27-v7/vcl-n-001_27-v7.vmx 8239372 8239365 vmx-svga:vcl-n-001:vmwarewin7-SocialScience27-v7 (shared) /bin/vmx -s sched.group=host/user -# product=2;name=VMware ESX;version=5.5.0;buildnumber=1331820;licensename=VMware ESX Server;licenseversion=5.0; -@ duplex=3;msgs=ui /vmfs/volumes/5284a6b9-9d90bf28-a89e-d89d67260538/vcl-n-001_27-v7/vcl-n-001_27-v7.vmx 8239373 8239365 vmx-vcpu-0:vcl-n-001:vmwarewin7-SocialScience27-v7 (shared) /bin/vmx -s sched.group=host/user -# product=2;name=VMware ESX;version=5.5.0;buildnumber=1331820;licensename=VMware ESX Server;licenseversion=5.0; -@ duplex=3;msgs=ui /vmfs/volumes/5284a6b9-9d90bf28-a89e-d89d67260538/vcl-n-001_27-v7/vcl-n-001_27-v7.vmx David DeMizio *Academic Systems Coordinator* Office of Information Technology New College of Florida Phone: 941-487-4222 | Fax: 941-487-4356 www.ncf.edu On Thu, Apr 3, 2014 at 12:28 PM, Andy Kurth <[email protected]> wrote: > Thanks for the vcld.log output, saw it after I sent my previous > message. Are there any lines containing "get_registered_vms" in > vcld.log? This would list the VMs it though was registered and would > be helpful to determine if VCL is correctly finding registered VMs and > parsing the names. > > What VMs do you see in the vSphere client? Do you don't see any VMs > named vcl-n-001*? > > If you have SSH or console access to the host, try running: > ps -c |grep '/bin/vmx .*vcl-n-001' > > Does this show any running processes? > > On Thu, Apr 3, 2014 at 12:11 PM, Andy Kurth <[email protected]> wrote: > > The original message was a reload attempt for vcl-n-004. The "MAC > > addresses do not match" line is expected since it was looking at > > vcl-n-001's vmx file. > > > > The vcld.log output in the 2nd message was a reload attempt for > > vcl-n-001. The code found an existing vmx file for this VM: > > vcl-n-001_27. It checked if this vmx file was registered and > > determined it was not. Because of this, it didn't attempt to > > unregister a VM and went straight to attempting to delete the > > directory. For some reason, this failed. > > > > Everything in the log output you provided looks to be working as > > intended from the VCL perspective. More information is necessary to > > determine what cause the deletion to fail. The full output from > > vcld.log would be helpful. > > > > Is the vcl_workspace datastore shared by multiple hosts? This error > > would occur if the VM was loaded on another host using the same > > datastore. > > > > If the datastore isn't shared, there may have been a problem on the > > host. Check /var/log/vmware/hostd.log and search for > > "CannotDeleteFile". If the problem occurred before VMware archived > > hostd.log, you may have to look in one of the hostd-xxxx.log.gz file > > which corresponds to the date the error occurred. If you find the > > corresponding CannotDeleteFile fault in hostd.log, there may be more > > details. > > > > -Andy > > > > On Thu, Apr 3, 2014 at 11:08 AM, Mike Haudenschild <[email protected]> > wrote: > >> Hi David, > >> > >> I'm fixated on this line in the log: > >> > >> 2014-04-02 > >> > 11:07:09|22252|91:91|reload|VMware.pm:get_active_vmx_file_path(1026)|ignoring > >> vcl-n-001_27-v8.vmx because MAC addresses do not match the ones being > used > >> by vcl-n-004 > >> > >> The fact you can reload a VM means that VCL is talking to VMWare, but > if the > >> MAC address isn't what VCL expects it might be assuming that's not the > VM > >> it's looking for when it's searching for / confirming it found the > correct > >> VM to shut down. If VCL cannot shut down the VM, it probably wouldn't > be > >> able to delete the .vmx file because it would still be in use by the > >> hypervisor. > >> > >> Regards, > >> Mike > >> > >> > >> On Thu, Apr 3, 2014 at 10:36 AM, David DeMizio <[email protected]> > wrote: > >>> > >>> Hello, > >>> > >>> any other ideas on what might be causing this. I can post more logs if > >>> needed. Thank You > >>> > >>> > >>> > >>> > >>> > >>> On Wed, Apr 2, 2014 at 1:28 PM, David DeMizio <[email protected]> > wrote: > >>>> > >>>> I took the following steps: > >>>> > >>>> 1) I powered off the vm manually( so VCL must not be able to power off > >>>> the vm) > >>>> 2) I reloaded the machine and it was successful, VCL was now able to > >>>> delete the file because vm was powered off > >>>> > >>>> however, it left the old vm in the inventory so I had to manually > remove > >>>> from inventory using the vsphere client. > >>>> > >>>> > >>>> > >>>> > >>>> > >>>> On Wed, Apr 2, 2014 at 12:47 PM, Dmitri Chebotarov <[email protected]> > >>>> wrote: > >>>>> > >>>>> Hi David > >>>>> > >>>>> Is the problem with VCL not able to shutdown running VM? Or it cannot > >>>>> delete file/folder? > >>>>> > >>>>> If VM is off, can you try to delete file/folder manually from vSphere > >>>>> client? > >>>>> > >>>>> -- > >>>>> Thank you, > >>>>> > >>>>> Dmitri Chebotarov > >>>>> VCL Sys Eng, Engineering & Architectural Support, TSD - Ent Servers & > >>>>> Messaging > >>>>> 223 Aquia Building, Ffx, MSN: 1B5 > >>>>> Phone: (703) 993-6175 | Fax: (703) 993-3404 > >>>>> > >>>>> > >>>>> On Apr 2, 2014, at 11:54 , David DeMizio <[email protected]> wrote: > >>>>> > >>>>> > They all appear to be mounted and I can browse the datastore from > >>>>> > vcenter. path looks good.. > >>>>> > > >>>>> > > >>>>> > David DeMizio > >>>>> > Academic Systems Coordinator > >>>>> > Office of Information Technology > >>>>> > New College of Florida > >>>>> > Phone: 941-487-4222 | Fax: 941-487-4356 > >>>>> > www.ncf.edu > >>>>> > > >>>>> > > >>>>> > On Wed, Apr 2, 2014 at 11:43 AM, António Aragão < > [email protected]> > >>>>> > wrote: > >>>>> > Inspect that all your repositories are well mounted. See if the > paths > >>>>> > are ok. > >>>>> > > >>>>> > 2014-04-02 16:39 GMT+01:00 David DeMizio <[email protected]>: > >>>>> > > I have added some more logs. basically it can't delete the vm > files. > >>>>> > > > >>>>> > > 2014-04-02 > >>>>> > > 11:20:34|23809|94:94|reload|VMware.pm:is_vm_registered(4427)|VM > >>>>> > > is not registered: > >>>>> > > '/vmfs/volumes/vcl_workspace/vcl-n-001_27-v8/vcl-n-001_27-v8.vmx' > >>>>> > > 2014-04-02 > >>>>> > > > 11:20:34|23809|94:94|reload|VMware.pm:get_vmx_info(5313)|attempting > >>>>> > > to > >>>>> > > retrieve info from vmx file: > >>>>> > > /vmfs/volumes/vcl_workspace/vcl-n-001_27-v8/vcl-n-001_27-v8.vmx > >>>>> > > 2014-04-02 > >>>>> > > > >>>>> > > > 11:20:34|23809|94:94|reload|Module.pm:code_loop_timeout(887)|attempting to > >>>>> > > copy file from VM host to management node: > >>>>> > > nc-vcenter:'[vcl_workspace] > >>>>> > > vcl-n-001_27-v8/vcl-n-001_27-v8.vmx' --> > >>>>> > > '/tmp/C387xsQmYu/vcl-n-001_27-v8.vmx', maximum of 50 seconds > >>>>> > > 2014-04-02 > >>>>> > > 11:20:34|23809|94:94|reload|vSphere_SDK.pm:__ANON__(1812)|copied > >>>>> > > file from VM host to management node: > >>>>> > > nc-vcenter.network.ncf.edu:'[vcl_workspace] > >>>>> > > vcl-n-001_27-v8/vcl-n-001_27-v8.vmx' --> > >>>>> > > '/tmp/C387xsQmYu/vcl-n-001_27-v8.vmx' > >>>>> > > 2014-04-02 > >>>>> > > > >>>>> > > > 11:20:34|23809|94:94|reload|Module.pm:code_loop_timeout(900)|attempting to > >>>>> > > copy file from VM host to management node: > >>>>> > > nc-vcenter:'[vcl_workspace] > >>>>> > > vcl-n-001_27-v8/vcl-n-001_27-v8.vmx' --> > >>>>> > > '/tmp/C387xsQmYu/vcl-n-001_27-v8.vmx', code returned true > >>>>> > > 2014-04-02 > >>>>> > > > >>>>> > > > 11:20:34|23809|94:94|reload|vSphere_SDK.pm:get_file_contents(1874)|retrieved > >>>>> > > 99 lines from file: '/tmp/C387xsQmYu/vcl-n-001_27-v8.vmx' > >>>>> > > 2014-04-02 > >>>>> > > 11:20:34|23809|94:94|reload|VMware.pm:get_vmx_info(5399)|vmdk > >>>>> > > path appears to be relative: > >>>>> > > vmwarewin7-SocialScience27-v8-000001.vmdk, > >>>>> > > prepending the vmx directory: > >>>>> > > > >>>>> > > > /vmfs/volumes/vcl_workspace/vcl-n-001_27-v8/vmwarewin7-SocialScience27-v8-000001.vmdk > >>>>> > > 2014-04-02 > >>>>> > > 11:20:34|23809|94:94|reload|VMware.pm:delete_vm(5580)|attempting > >>>>> > > to delete vmx directory: > /vmfs/volumes/vcl_workspace/vcl-n-001_27-v8 > >>>>> > > 2014-04-02 > >>>>> > > > >>>>> > > > 11:20:34|23809|94:94|reload|vSphere_SDK.pm:delete_file(1596)|attempting to > >>>>> > > delete file: [vcl_workspace] vcl-n-001_27-v8 > >>>>> > > 2014-04-02 11:20:35|23413|vcld:main(167)|lastcheckin time updated > >>>>> > > for > >>>>> > > management node 1: 2014-04-02 11:20:35 > >>>>> > > 2014-04-02 11:20:40|23413|vcld:main(167)|lastcheckin time updated > >>>>> > > for > >>>>> > > management node 1: 2014-04-02 11:20:40 > >>>>> > > 2014-04-02 11:20:45|23413|vcld:main(167)|lastcheckin time updated > >>>>> > > for > >>>>> > > management node 1: 2014-04-02 11:20:45 > >>>>> > > 2014-04-02 11:20:50|23413|vcld:main(167)|lastcheckin time updated > >>>>> > > for > >>>>> > > management node 1: 2014-04-02 11:20:50 > >>>>> > > 2014-04-02 11:20:55|23413|vcld:main(167)|lastcheckin time updated > >>>>> > > for > >>>>> > > management node 1: 2014-04-02 11:20:55 > >>>>> > > 2014-04-02 11:21:00|23413|vcld:main(167)|lastcheckin time updated > >>>>> > > for > >>>>> > > management node 1: 2014-04-02 11:21:00 > >>>>> > > 2014-04-02 11:21:05|23413|vcld:main(167)|lastcheckin time updated > >>>>> > > for > >>>>> > > management node 1: 2014-04-02 11:21:05 > >>>>> > > > >>>>> > > |23809|94:94|reload| ---- WARNING ---- > >>>>> > > |23809|94:94|reload| 2014-04-02 > >>>>> > > > 11:21:07|23809|94:94|reload|vSphere_SDK.pm:delete_file(1604)|failed > >>>>> > > to > >>>>> > > delete file: [vcl_workspace] vcl-n-001_27-v8, error: > >>>>> > > |23809|94:94|reload| SOAP Fault: > >>>>> > > |23809|94:94|reload| ----------- > >>>>> > > |23809|94:94|reload| Fault string: Cannot delete file > >>>>> > > [vcl_workspace] > >>>>> > > vcl-n-001_27-v8 > >>>>> > > |23809|94:94|reload| Fault detail: CannotDeleteFile > >>>>> > > |23809|94:94|reload| ( 0) vSphere_SDK.pm, delete_file (line: > 1604) > >>>>> > > |23809|94:94|reload| (-1) VMware.pm, delete_vm (line: 5583) > >>>>> > > |23809|94:94|reload| (-2) VMware.pm, remove_existing_vms (line: > >>>>> > > 1612) > >>>>> > > |23809|94:94|reload| (-3) VMware.pm, load (line: 469) > >>>>> > > |23809|94:94|reload| (-4) new.pm, reload_image (line: 671) > >>>>> > > |23809|94:94|reload| (-5) new.pm, process (line: 291) > >>>>> > > > >>>>> > > > >>>>> > > > >>>>> > > > >>>>> > > > >>>>> > > > >>>>> > > On Wed, Apr 2, 2014 at 11:29 AM, David DeMizio <[email protected] > > > >>>>> > > wrote: > >>>>> > >> > >>>>> > >> I have not been using VCL for about a week or so and all of a > >>>>> > >> sudden I > >>>>> > >> can't reload images. Below is part of the log. Any ideas? > >>>>> > >> > >>>>> > >> VM is still running after attempting to delete all existing > >>>>> > >> matching VMs: > >>>>> > >> vcl-n-004 (10.10.12.44), unable to determine vmx file path > >>>>> > >> > >>>>> > >> > ------------------------------------------------------------------------ > >>>>> > >> time: 2014-04-02 11:07:13 > >>>>> > >> caller: VMware.pm:remove_existing_vms(1629) > >>>>> > >> ( 0) VMware.pm, remove_existing_vms (line: 1629) > >>>>> > >> (-1) VMware.pm, load (line: 469) > >>>>> > >> (-2) new.pm, reload_image (line: 671) > >>>>> > >> (-3) new.pm, process (line: 291) > >>>>> > >> (-4) vcld, make_new_child (line: 571) > >>>>> > >> (-5) vcld, main (line: 350) > >>>>> > >> > >>>>> > >> > ------------------------------------------------------------------------ > >>>>> > >> > >>>>> > >> reservation PID: 22252 > >>>>> > >> parent vcld PID: 23413 > >>>>> > >> > >>>>> > >> request ID: 91 > >>>>> > >> reservation ID: 91 > >>>>> > >> request state/laststate: reload/inuse > >>>>> > >> request start time: 2014-04-02 10:58:50 > >>>>> > >> request end time: 2014-04-02 11:28:50 > >>>>> > >> for imaging: no > >>>>> > >> log ID: none > >>>>> > >> > >>>>> > >> computer: vcl-n-004 > >>>>> > >> computer id: 7 > >>>>> > >> computer type: virtualmachine > >>>>> > >> computer eth0 MAC address: 00:50:56:00:A0:04 > >>>>> > >> computer eth1 MAC address: <undefined> > >>>>> > >> computer private IP address: 10.10.12.44 > >>>>> > >> computer public IP address: 10.10.11.52 > >>>>> > >> computer in block allocation: no > >>>>> > >> provisioning module: VCL::Module::Provisioning::VMware::VMware > >>>>> > >> > >>>>> > >> > >>>>> > >> vm host ID: 2 > >>>>> > >> vm host computer ID: 9 > >>>>> > >> vm profile: VMware vCenter > >>>>> > >> vm profile VM path: /vmfs/volumes/vcl_workspace > >>>>> > >> vm profile repository path: <undefined> > >>>>> > >> vm profile datastore path: /vmfs/volumes/vcl_master > >>>>> > >> vm profile disk type: shared > >>>>> > >> > >>>>> > >> image: vmwarewin7-SocialScience27-v8 > >>>>> > >> image display name: SSRL > >>>>> > >> image ID: 27 > >>>>> > >> image revision ID: 45 > >>>>> > >> image size: 43138 MB > >>>>> > >> use Sysprep: no > >>>>> > >> root access: yes > >>>>> > >> image owner ID: 1 > >>>>> > >> image owner affiliation: Local > >>>>> > >> image revision date created: 2014-03-06 10:00:57 > >>>>> > >> image revision production: yes > >>>>> > >> OS module: VCL::Module::OS::Windows::Version_6::7 > >>>>> > >> image revision comments: Added Labs Shortcut to Desktop > >>>>> > >> > >>>>> > >> user: vclreload > >>>>> > >> user name: vcl reload > >>>>> > >> user ID: 2 > >>>>> > >> user affiliation: Local > >>>>> > >> > >>>>> > >> > ------------------------------------------------------------------------ > >>>>> > >> RECENT LOG ENTRIES FOR THIS PROCESS: > >>>>> > >> 2014-04-02 > >>>>> > >> > >>>>> > >> > 11:07:09|22252|91:91|reload|VMware.pm:get_active_vmx_file_path(1026)|ignoring > >>>>> > >> vcl-n-001_27-v8.vmx because MAC addresses do not match the ones > >>>>> > >> being used > >>>>> > >> by vcl-n-004 > >>>>> > >> 2014-04-02 > >>>>> > >> > 11:07:09|22252|91:91|reload|VMware.pm:get_vmx_info(5313)|attempting > >>>>> > >> to > >>>>> > >> retrieve info from vmx file: > >>>>> > >> /vmfs/volumes/vcl_workspace/vcl-n-002_27-v8/vcl-n-002_27-v8.vmx > >>>>> > >> 2014-04-02 > >>>>> > >> > >>>>> > >> > 11:07:09|22252|91:91|reload|Module.pm:code_loop_timeout(887)|attempting to > >>>>> > >> copy file from VM host to management node: > >>>>> > >> nc-vcenter.network.ncf.edu:'[vcl_workspace] > >>>>> > >> vcl-n-002_27-v8/vcl-n-002_27-v8.vmx' > >>>>> > >> > >>>>> > >> > >>>>> > > > >>>>> > > >>>>> > > >>>>> > > >>>>> > -- > >>>>> > > http://www.di.uminho.pt/~apa/email/cartao_virtual_email_aaragao.png > >>>>> > > >>>>> > >>>> > >>> > >> >
