Hi,
When I enable the zone, the systemvm creation begins but goes into a loop of
creating and deleting VMs in vCenter. I see in the logs there is an error for
creating the folder permissions on the secondary storage (see below). Running
this CHMOD manually from inside the CSM kicks the same error.
Please provide suggestions.
2020-07-02 09:08:39,665 DEBUG [c.c.h.v.m.VmwareManagerImpl]
(DirectAgent-66:ctx-e15c32b2 usphlmvesxt154.phl.global.corp.sap, job-16/job-35,
cmd: CopyCommand) (logid:1cfa64a9) Executing: sudo chmod 1777
/var/cloudstack/mnt/VM/345050029058.2807345c
2020-07-02 09:08:39,666 DEBUG [c.c.h.v.m.VmwareManagerImpl]
(DirectAgent-66:ctx-e15c32b2 usphlmvesxt154.phl.global.corp.sap, job-16/job-35,
cmd: CopyCommand) (logid:1cfa64a9) Executing while with timeout : 1440000
2020-07-02 09:08:39,693 DEBUG [c.c.h.v.m.VmwareManagerImpl]
(DirectAgent-66:ctx-e15c32b2 usphlmvesxt154.phl.global.corp.sap, job-16/job-35,
cmd: CopyCommand) (logid:1cfa64a9) Exit value is 1
2020-07-02 09:08:39,697 DEBUG [c.c.h.v.m.VmwareManagerImpl]
(DirectAgent-66:ctx-e15c32b2 usphlmvesxt154.phl.global.corp.sap, job-16/job-35,
cmd: CopyCommand) (logid:1cfa64a9) chmod: changing permissions of
'/var/cloudstack/mnt/VM/345050029058.2807345c': Operation not permitted
2020-07-02 09:08:39,699 WARN [c.c.h.v.m.VmwareManagerImpl]
(DirectAgent-66:ctx-e15c32b2 usphlmvesxt154.phl.global.corp.sap, job-16/job-35,
cmd: CopyCommand) (logid:1cfa64a9) Unable to set permissions for
/var/cloudstack/mnt/VM/345050029058.2807345c due to chmod: changing permissions
of '/var/cloudstack/mnt/VM/345050029058.2807345c': Operation not permitted
Lines...
2020-07-02 09:09:00,598 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-17:ctx-681dc524
usphlmvesxt154.phl.global.corp.sap, job-16/job-35, cmd: StartCommand)
(logid:1cfa64a9) find VM v-2-VM on host
2020-07-02 09:09:00,598 INFO [c.c.h.v.m.HostMO] (DirectAgent-17:ctx-681dc524
usphlmvesxt154.phl.global.corp.sap, job-16/job-35, cmd: StartCommand)
(logid:1cfa64a9) VM v-2-VM not found in host cache
2020-07-02 09:09:00,598 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-17:ctx-681dc524
usphlmvesxt154.phl.global.corp.sap, job-16/job-35, cmd: StartCommand)
(logid:1cfa64a9) load VM cache on host
2020-07-02 09:09:00,616 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-17:ctx-681dc524
usphlmvesxt154.phl.global.corp.sap, job-16/job-35, cmd: StartCommand)
(logid:1cfa64a9) find VM v-2-VM on host
2020-07-02 09:09:00,617 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-17:ctx-681dc524
usphlmvesxt154.phl.global.corp.sap, job-16/job-35, cmd: StartCommand)
(logid:1cfa64a9) VM v-2-VM found in host cache
2020-07-02 09:09:00,799 ERROR [c.c.h.v.m.VmwareManagerImpl]
(DirectAgent-17:ctx-681dc524 usphlmvesxt154.phl.global.corp.sap, job-16/job-35,
cmd: StartCommand) (logid:1cfa64a9) Unable to create systemvm folder on
secondary storage. location:
/var/cloudstack/mnt/VM/345050029058.2807345c/systemvm
2020-07-02 09:09:00,800 INFO [c.c.h.v.u.VmwareHelper]
(DirectAgent-17:ctx-681dc524 usphlmvesxt154.phl.global.corp.sap, job-16/job-35,
cmd: StartCommand) (logid:1cfa64a9) [ignored]failed to get message for
exception: Unable to create systemvm folder on secondary storage. location:
/var/cloudstack/mnt/VM/345050029058.2807345c/systemvm
2020-07-02 09:09:00,800 WARN [c.c.h.v.r.VmwareResource]
(DirectAgent-17:ctx-681dc524 usphlmvesxt154.phl.global.corp.sap, job-16/job-35,
cmd: StartCommand) (logid:1cfa64a9) StartCommand failed due to Exception:
com.cloud.utils.exception.CloudRuntimeException
Message: Unable to create systemvm folder on secondary storage. location:
/var/cloudstack/mnt/VM/345050029058.2807345c/systemvm
com.cloud.utils.exception.CloudRuntimeException: Unable to create systemvm
folder on secondary storage. location:
/var/cloudstack/mnt/VM/345050029058.2807345c/systemvm
at
com.cloud.hypervisor.vmware.manager.VmwareManagerImpl.prepareSecondaryStorageStore(VmwareManagerImpl.java:648)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:95)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
at com.sun.proxy.$Proxy389.prepareSecondaryStorageStore(Unknown
Source)
at
com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:1962)
at
com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:530)
at
com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:315)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
at
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at
java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at
java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:834)
2020-07-02 09:09:00,804 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-17:ctx-681dc524) (logid:1cfa64a9) Seq 1-4541880224203147245:
Cancelling because one of the answers is false and it is stop on error.
2020-07-02 09:09:00,804 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-17:ctx-681dc524) (logid:1cfa64a9) Seq 1-4541880224203147245:
Response Received:
2020-07-02 09:09:00,805 DEBUG [c.c.a.t.Request] (DirectAgent-17:ctx-681dc524)
(logid:1cfa64a9) Seq 1-4541880224203147245: Processing: { Ans: , MgmtId:
345050029058, via: 1(usphlmvesxt154.phl.global.corp.sap), Ver: v1, Flags: 110,
[{"com.cloud.agent.api.StartAnswer":{"vm":{"id":2,"name":"v-2-VM","bootloader":"HVM","state":"Starting","type":"ConsoleProxy","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":1073741824,"maxRam":1073741824,"hostName":"v-2-VM","arch":"x86_64","os":"Other
Linux (64-bit)","platformEmulator":"otherLinux64Guest","bootArgs":"
template=domP type=consoleproxy host=10.4.32.163 port=8250 name=v-2-VM zone=1
pod=1 guid=Proxy.2 proxy_vm=2 disable_rp_filter=true eth2ip=10.4.42.25
eth2mask=255.255.255.192 gateway=10.4.42.1 eth0ip=0.0.0.0 eth0mask=0.0.0.0
eth1ip=10.4.4.35 eth1mask=255.255.252.0 mgmtcidr=10.4.32.0/24 localgw=10.4.4.1
internaldns1=10.4.202.200 dns1=10.4.202.200
dns2=10.4.12.200","enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"sYnwDJYgzrMKdm3ftAO-kg","params":{"vmware.reserve.mem":"false","vmware.reserve.cpu":"false","nicAdapter":"E1000"},"uuid":"fb65df73-693d-48fb-a203-c2b5e776842a","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"9a1f2ae8-6b10-4525-8a54-a175b153b789","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"50cc970f-fbe2-3b45-9cb5-b8bcdb6dbff5","id":1,"poolType":"NetworkFilesystem","host":"usphlcv300.phl.global.corp.sap","path":"/usphlmvesx_lab_cspri","port":2049,"url":"NetworkFilesystem://usphlcv300.phl.global.corp.sap/usphlmvesx_lab_cspri/?ROLE=Primary&STOREUUID=50cc970f-fbe2-3b45-9cb5-b8bcdb6dbff5","isManaged":false}},"name":"ROOT-2","size":0,"path":"ROOT-2_2","volumeId":2,"vmName":"v-2-VM","accountId":1,"format":"OVA","provisioningType":"THIN","id":2,"deviceId":0,"bytesReadRate":0,"bytesWriteRate":0,"iopsReadRate":0,"iopsWriteRate":0,"hypervisorType":"VMware","directDownload":false}},"diskSeq":0,"path":"ROOT-2_2","type":"ROOT","_details":{"storageHost":"usphlcv300.phl.global.corp.sap","managed":"false","storagePort":"2049","volumeSize":"0"}}],"nics":[{"deviceId":2,"networkRateMbps":-1,"defaultNic":true,"pxeDisable":true,"nicUuid":"ffbc1822-7907-4cdf-9e80-bb316786e04d","details":{"PromiscuousMode":"false","MacAddressChanges":"true","ForgedTransmits":"true"},"dpdkEnabled":false,"uuid":"f3a30021-a469-413d-85a8-ca1ca68ba27c","ip":"10.4.42.25","netmask":"255.255.255.192","gateway":"10.4.42.1","mac":"1e:00:e3:00:00:19","dns1":"10.4.202.200","dns2":"10.4.12.200","broadcastType":"Vlan","type":"Public","broadcastUri":"vlan://untagged","isolationUri":"vlan://untagged","isSecurityGroupEnabled":false,"name":"vSwitch0,134,vmwaresvs"},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"pxeDisable":true,"nicUuid":"d6521be0-85b8-4836-bf8b-8461afdf593a","details":{"PromiscuousMode":"false","MacAddressChanges":"true","ForgedTransmits":"true"},"dpdkEnabled":false,"uuid":"eda0ae3d-d15d-4f91-b8db-a719cf5a94bf","mac":"02:00:31:71:00:02","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false,"name":"vSwitch0,146,vmwaresvs"},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"pxeDisable":true,"nicUuid":"4e6201ad-91c0-4cab-bf53-9e2440025245","details":{"PromiscuousMode":"false","MacAddressChanges":"true","ForgedTransmits":"true"},"dpdkEnabled":false,"uuid":"ce88b030-c04c-4437-b60d-9910c2cc376f","ip":"10.4.4.35","netmask":"255.255.252.0","gateway":"10.4.4.1","mac":"1e:00:6b:00:00:27","broadcastType":"Native","type":"Management","isSecurityGroupEnabled":false,"name":"vSwitch0,146,vmwaresvs"}],"guestOsDetails":{},"extraConfig":{}},"result":false,"details":"StartCommand
failed due to Exception:
com.cloud.utils.exception.CloudRuntimeException\nMessage: Unable to create
systemvm folder on secondary storage. location:
/var/cloudstack/mnt/VM/345050029058.2807345c/systemvm\n","wait":0}}] }
2020-07-02 09:09:00,805 DEBUG [c.c.a.m.AgentAttache]
(DirectAgent-17:ctx-681dc524) (logid:1cfa64a9) Seq 1-4541880224203147245: No
more commands found
2020-07-02 09:09:00,806 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-2:ctx-9aa38618 job-16/job-35 ctx-7ebd1b78) (logid:1cfa64a9)
Seq 1-4541880224203147245: Received: { Ans: , MgmtId: 345050029058, via:
1(usphlmvesxt154.phl.global.corp.sap), Ver: v1, Flags: 110, { StartAnswer } }
2020-07-02 09:09:00,816 INFO [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-2:ctx-9aa38618 job-16/job-35 ctx-7ebd1b78) (logid:1cfa64a9)
Unable to start VM on Host[-1-Routing] due to StartCommand failed due to
Exception: com.cloud.utils.exception.CloudRuntimeException
Message: Unable to create systemvm folder on secondary storage. location:
/var/cloudstack/mnt/VM/345050029058.2807345c/systemvm
Mike Corey
Technology Senior Consultant, IT CS CTW Operation & Virtualization Service US
SAP AMERICA, INC. 3999 West Chester Pike, Newtown Square, 19073 United States
T +1 610 661 0905, M +1 484 274 2658, E mike.co...@sap.com
[cid:image002.png@01D65056.54B16610]
