Hello folks,
Just upgraded to 4.15.1 from 4.15.0 and I get the following error for
systemvms, unable to check if agents are running because of "Failed to
authentication". I had not issue in a different env (from 4.14 to 4.15.1)
I want to mention that first, I had the issue with this :
"Copy System VM patch ISO file to secondary storage. source ISO:
/usr/share/cloudstack-common/vms/systemvm.iso, destination:
/var/cloudstack/mnt/VM/345049356158.5c045ec2/systemvm/systemvm-4.15.1.0.iso
2021-07-29 07:03:40,925 ERROR [c.c.h.v.m.VmwareManagerImpl]
(DirectAgent-94:ctx-568a9862 nsxxxxxx.ip-51-83-x.eu, job-33329/job-33579,
cmd: StartCommand) (logid:68ca6ba5) Unexpected exception
java.nio.file.AccessDeniedException:
/var/cloudstack/mnt/VM/345049356158.5c045ec2/systemvm/systemvm-4.15.1.0.iso"
I fixed this by changing the permissions in "systemvm folder"
"2021-07-29 07:31:16,605 ERROR [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-7:ctx-167802d6 job-33329/job-33685 ctx-e8692fdb)
(logid:68ca6ba5) Retrying after catching exception while trying to secure
agent for systemvm id=1905
com.cloud.utils.exception.CloudRuntimeException: Unable to read/process CSR:
Command failed due to Exception: java.lang.Exception
Message: Failed to authentication SSH user root on host 172.11.11.180
at
org.apache.cloudstack.ca.provider.RootCAProvider.generateCertificateUsingCsr
(RootCAProvider.java:170)
at
org.apache.cloudstack.ca.provider.RootCAProvider.issueCertificate(RootCAProv
ider.java:230)
at
org.apache.cloudstack.ca.CAManagerImpl.issueCertificate(CAManagerImpl.java:1
64)
at jdk.internal.reflect.GeneratedMethodAccessor377.invoke(Unknown
Source)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Delegatin
gMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopU
tils.java:344)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint
(ReflectiveMethodInvocation.java:198)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(Reflect
iveMethodInvocation.java:163)
at
org.apache.cloudstack.network.contrail.management.EventUtils$EventIntercepto
r.invoke(EventUtils.java:107)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(Reflect
iveMethodInvocation.java:175)
at
com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:51
)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(Reflect
iveMethodInvocation.java:175)
at
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(Expos
eInvocationInterceptor.java:97)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(Reflect
iveMethodInvocation.java:186)
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopPro
xy.java:215)
at com.sun.proxy.$Proxy292.issueCertificate(Unknown Source)
at
com.cloud.vm.VirtualMachineManagerImpl.setupAgentSecurity(VirtualMachineMana
gerImpl.java:970)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManage
rImpl.java:1241)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManage
rImpl.java:5502)
at jdk.internal.reflect.GeneratedMethodAccessor542.invoke(Unknown
Source)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Delegatin
gMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.jav
a:107)
at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManager
Impl.java:5669)
at
com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext
(AsyncJobManagerImpl.java:620)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedCo
ntextRunnable.java:48)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(Defa
ultManagedContext.java:55)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithCon
text(DefaultManagedContext.java:102)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithCont
ext(DefaultManagedContext.java:52)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedCont
extRunnable.java:45)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJob
ManagerImpl.java:568)
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.ThreadPoolExecutor.runWorker(ThreadPoolExecut
or.java:1128)
at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecu
tor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)
2021-07-29 07:31:16,607 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-7:ctx-167802d6 job-33329/job-33685 ctx-e8692fdb)
(logid:68ca6ba5) Seq 20-8610038062602257728: Sending { Cmd , MgmtId:
345049356158, via: 20(nsxxxxxx.ip-51-83-x.eu), Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.ca.SetupKeyStoreCommand":{"handleByAgent":"false","
accessDetails":{"router.name":"s-1905-VM","router.guest.ip":"1xx.202.36.49",
"Management":"172.11.11.180","router.ip":"172.11.11.180","Guest":"1xx.202.36
.49"},"wait":"60","bypassHostMaintenance":"false"}}] }
2021-07-29 07:31:16,608 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-7:ctx-167802d6 job-33329/job-33685 ctx-e8692fdb)
(logid:68ca6ba5) Seq 20-8610038062602257728: Executing: { Cmd , MgmtId:
345049356158, via: 20(nsxxxxxx.ip-51-83-x.eu), Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.ca.SetupKeyStoreCommand":{"handleByAgent":"false","
accessDetails":{"router.name":"s-1905-VM","router.guest.ip":"1xx.202.36.49",
"Management":"172.11.11.180","router.ip":"172.11.11.180","Guest":"1xx.202.36
.49"},"wait":"60","bypassHostMaintenance":"false"}}] }
2021-07-29 07:31:16,608 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-272:ctx-935572dd) (logid:c1c5c59c) Seq 20-8610038062602257728:
Executing request
2021-07-29 07:31:16,608 DEBUG [c.c.h.v.r.VmwareResource]
(DirectAgent-272:ctx-935572dd nsxxxxxx.ip-51-83-x.eu, job-33329/job-33685,
cmd: SetupKeyStoreCommand) (logid:68ca6ba5) Use router's private IP for SSH
control. IP : 172.11.11.180
2021-07-29 07:31:16,608 DEBUG [c.c.h.v.r.VmwareResource]
(DirectAgent-272:ctx-935572dd nsxxxxxx.ip-51-83-x.eu, job-33329/job-33685,
cmd: SetupKeyStoreCommand) (logid:68ca6ba5) Run command on VR:
172.11.11.180, script: keystore-setup with args:
/usr/local/cloud/systemvm/conf/agent.properties
/usr/local/cloud/systemvm/conf/cloud.jks ej3AuFWgYHZGJZ44 365
/usr/local/cloud/systemvm/conf/cloud.csr
2021-07-29 07:31:16,837 ERROR [c.c.u.s.SshHelper]
(DirectAgent-272:ctx-935572dd nsxxxxxx.ip-51-83-x.eu, job-33329/job-33685,
cmd: SetupKeyStoreCommand) (logid:68ca6ba5) Failed to authentication SSH
user root on host 172.11.11.180
2021-07-29 07:31:16,837 INFO [c.c.h.v.u.VmwareHelper]
(DirectAgent-272:ctx-935572dd nsxxxxxx.ip-51-83-x.eu, job-33329/job-33685,
cmd: SetupKeyStoreCommand) (logid:68ca6ba5) [ignored]failed to get message
for exception: Failed to authentication SSH user root on host 172.11.11.180
2021-07-29 07:31:16,837 ERROR [c.c.h.v.r.VmwareResource]
(DirectAgent-272:ctx-935572dd nsxxxxxx.ip-51-83-x.eu, job-33329/job-33685,
cmd: SetupKeyStoreCommand) (logid:68ca6ba5) Command failed due to Exception:
java.lang.Exception
Message: Failed to authentication SSH user root on host 172.11.11.180
2021-07-29 07:31:16,837 DEBUG [c.c.h.v.r.VmwareResource]
(DirectAgent-272:ctx-935572dd nsxxxxxx.ip-51-83-x.eu, job-33329/job-33685,
cmd: SetupKeyStoreCommand) (logid:68ca6ba5) keystore-setup execution result:
false
2021-07-29 07:31:16,837 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-272:ctx-935572dd) (logid:68ca6ba5) Seq 20-8610038062602257728:
Response Received:
2021-07-29 07:31:16,838 DEBUG [c.c.a.t.Request]
(DirectAgent-272:ctx-935572dd) (logid:68ca6ba5) Seq 20-8610038062602257728:
Processing: { Ans: , MgmtId: 345049356158, via: 20(nsxxxxxx.ip-51-83-x.eu),
Ver: v1, Flags: 10,
[{"org.apache.cloudstack.ca.SetupKeystoreAnswer":{"result":"true","wait":"0"
,"bypassHostMaintenance":"false"}}] }
2021-07-29 07:31:16,838 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-7:ctx-167802d6 job-33329/job-33685 ctx-e8692fdb)
(logid:68ca6ba5) Seq 20-8610038062602257728: Received: { Ans: , MgmtId:
345049356158, via: 20(nsxxxxxx.ip-51-83-x.eu), Ver: v1, Flags: 10, {
SetupKeystoreAnswer } }
2021-07-29 07:31:16,848 ERROR [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-7:ctx-167802d6 job-33329/job-33685 ctx-e8692fdb)
(logid:68ca6ba5) Retrying after catching exception while trying to secure
agent for systemvm id=1905
com.cloud.utils.exception.CloudRuntimeException: Unable to read/process CSR:
Command failed due to Exception: java.lang.Exception
Message: Failed to authentication SSH user root on host 172.11.11.180
at
org.apache.cloudstack.ca.provider.RootCAProvider.generateCertificateUsingCsr
(RootCAProvider.java:170)
at
org.apache.cloudstack.ca.provider.RootCAProvider.issueCertificate(RootCAProv
ider.java:230)
at
org.apache.cloudstack.ca.CAManagerImpl.issueCertificate(CAManagerImpl.java:1
64)
at jdk.internal.reflect.GeneratedMethodAccessor377.invoke(Unknown
Source)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Delegatin
gMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopU
tils.java:344)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint
(ReflectiveMethodInvocation.java:198)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(Reflect
iveMethodInvocation.java:163)
at
org.apache.cloudstack.network.contrail.management.EventUtils$EventIntercepto
r.invoke(EventUtils.java:107)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(Reflect
iveMethodInvocation.java:175)
at
com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:51
)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(Reflect
iveMethodInvocation.java:175)
at
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(Expos
eInvocationInterceptor.java:97)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(Reflect
iveMethodInvocation.java:186)
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopPro
xy.java:215)
at com.sun.proxy.$Proxy292.issueCertificate(Unknown Source)
at
com.cloud.vm.VirtualMachineManagerImpl.setupAgentSecurity(VirtualMachineMana
gerImpl.java:970)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManage
rImpl.java:1241)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManage
rImpl.java:5502)
at jdk.internal.reflect.GeneratedMethodAccessor542.invoke(Unknown
Source)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Delegatin
gMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.jav
a:107)
at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManager
Impl.java:5669)
at
com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext
(AsyncJobManagerImpl.java:620)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedCo
ntextRunnable.java:48)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(Defa
ultManagedContext.java:55)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithCon
text(DefaultManagedContext.java:102)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithCont
ext(DefaultManagedContext.java:52)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedCont
extRunnable.java:45)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJob
ManagerImpl.java:568)
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.ThreadPoolExecutor.runWorker(ThreadPoolExecut
or.java:1128)
at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecu
tor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)
2021-07-29 07:31:16,849 INFO [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-7:ctx-167802d6 job-33329/job-33685 ctx-e8692fdb)
(logid:68ca6ba5) Caught CloudRuntimeException, returning job failed
com.cloud.utils.exception.CloudRuntimeException: Failed to setup and secure
agent for systemvm id=1905
2021-07-29 07:31:16,849 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-7:ctx-167802d6 job-33329/job-33685 ctx-e8692fdb)
(logid:68ca6ba5) Done executing VM work job:
com.cloud.vm.VmWorkStart{"dcId":0,"userId":1,"accountId":1,"vmId":1905,"hand
lerName":"VirtualMachineManagerImpl"}
2021-07-29 07:31:16,849 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-7:ctx-167802d6 job-33329/job-33685 ctx-e8692fdb)
(logid:68ca6ba5) Complete async job-33685, jobStatus: FAILED, resultCode: 0,
result:
rO0ABXNyAC9jb20uY2xvdWQudXRpbHMuZXhjZXB0aW9uLkNsb3VkUnVudGltZUV4Y2VwdGlvbgAA
AABWTU9yAwABSQALY3NFcnJvckNvZGV4cgAaamF2YS5sYW5nLlJ1bnRpbWVFeGNlcHRpb26eXwZH
CjSD5QIAAHhyABNqYXZhLmxhbmcuRXhjZXB0aW9u0P0fPho7HMQCAAB4cgATamF2YS5sYW5nLlRo
cm93YWJsZdXGNSc5d7jLAwAETAAFY2F1c2V0ABVMamF2YS9sYW5nL1Rocm93YWJsZTtMAA1kZXRh
aWxNZXNzYWdldAASTGphdmEvbGFuZy9TdHJpbmc7WwAKc3RhY2tUcmFjZXQAHltMamF2YS9sYW5n
L1N0YWNrVHJhY2VFbGVtZW50O0wAFHN1cHByZXNzZWRFeGNlcHRpb25zdAAQTGphdmEvdXRpbC9M
aXN0O3hwcQB-AAh0ABtVbmFibGUgdG8gc3RhcnQgVk0gaW5zdGFuY2V1cgAeW0xqYXZhLmxhbmcu
U3RhY2tUcmFjZUVsZW1lbnQ7AkYqPDz9IjkCAAB4cAAAABNzcgAbamF2YS5sYW5nLlN0YWNrVHJh
Y2VFbGVtZW50YQnFmiY23YUCAAhCAAZmb3JtYXRJAApsaW5lTnVtYmVyTAAPY2xhc3NMb2FkZXJO
YW1lcQB-AAVMAA5kZWNsYXJpbmdDbGFzc3EAfgAFTAAIZmlsZU5hbWVxAH4ABUwACm1ldGhvZE5h
bWVxAH4ABUwACm1vZHVsZU5hbWVxAH4ABUwADW1vZHVsZVZlcnNpb25xAH4ABXhwAQAAFYN0AANh
cHB0ACZjb20uY2xvdWQudm0uVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbHQAHlZpcnR1YWxNYWNo
aW5lTWFuYWdlckltcGwuamF2YXQAEG9yY2hlc3RyYXRlU3RhcnRwcHNxAH4ADAD_____cHQAL2pk
ay5pbnRlcm5hbC5yZWZsZWN0LkdlbmVyYXRlZE1ldGhvZEFjY2Vzc29yNTQycHQABmludm9rZXBw
c3EAfgAMAgAAACtwdAAxamRrLmludGVybmFsLnJlZmxlY3QuRGVsZWdhdGluZ01ldGhvZEFjY2Vz
c29ySW1wbHQAIURlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGwuamF2YXEAfgAUdAAJamF2YS5i
YXNldAAHMTEuMC4xMnNxAH4ADAIAAAI2cHQAGGphdmEubGFuZy5yZWZsZWN0Lk1ldGhvZHQAC01l
dGhvZC5qYXZhcQB-ABRxAH4AGHEAfgAZc3EAfgAMAQAAAGtxAH4ADnQAImNvbS5jbG91ZC52bS5W
bVdvcmtKb2JIYW5kbGVyUHJveHl0ABpWbVdvcmtKb2JIYW5kbGVyUHJveHkuamF2YXQAD2hhbmRs
ZVZtV29ya0pvYnBwc3EAfgAMAQAAFiVxAH4ADnEAfgAPcQB-ABBxAH4AIHBwc3EAfgAMAQAAAGZx
AH4ADnQAIGNvbS5jbG91ZC52bS5WbVdvcmtKb2JEaXNwYXRjaGVydAAYVm1Xb3JrSm9iRGlzcGF0
Y2hlci5qYXZhdAAGcnVuSm9icHBzcQB-AAwBAAACbHEAfgAOdAA_b3JnLmFwYWNoZS5jbG91ZHN0
YWNrLmZyYW1ld29yay5qb2JzLmltcGwuQXN5bmNKb2JNYW5hZ2VySW1wbCQ1dAAYQXN5bmNKb2JN
YW5hZ2VySW1wbC5qYXZhdAAMcnVuSW5Db250ZXh0cHBzcQB-AAwBAAAAMHEAfgAOdAA-b3JnLmFw
YWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlJDF0
ABtNYW5hZ2VkQ29udGV4dFJ1bm5hYmxlLmphdmF0AANydW5wcHNxAH4ADAEAAAA3cQB-AA50AEJv
cmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRD
b250ZXh0JDF0ABpEZWZhdWx0TWFuYWdlZENvbnRleHQuamF2YXQABGNhbGxwcHNxAH4ADAEAAABm
cQB-AA50AEBvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVs
dE1hbmFnZWRDb250ZXh0cQB-ADB0AA9jYWxsV2l0aENvbnRleHRwcHNxAH4ADAEAAAA0cQB-AA5x
AH4AM3EAfgAwdAAOcnVuV2l0aENvbnRleHRwcHNxAH4ADAEAAAAtcQB-AA50ADxvcmcuYXBhY2hl
LmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGVxAH4ALHEA
fgAtcHBzcQB-AAwBAAACOHEAfgAOcQB-ACdxAH4AKHEAfgAtcHBzcQB-AAwCAAACA3B0AC5qYXZh
LnV0aWwuY29uY3VycmVudC5FeGVjdXRvcnMkUnVubmFibGVBZGFwdGVydAAORXhlY3V0b3JzLmph
dmFxAH4AMXEAfgAYcQB-ABlzcQB-AAwCAAABCHB0AB9qYXZhLnV0aWwuY29uY3VycmVudC5GdXR1
cmVUYXNrdAAPRnV0dXJlVGFzay5qYXZhcQB-AC1xAH4AGHEAfgAZc3EAfgAMAgAABGhwdAAnamF2
YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9ydAAXVGhyZWFkUG9vbEV4ZWN1dG9y
LmphdmF0AAlydW5Xb3JrZXJxAH4AGHEAfgAZc3EAfgAMAgAAAnRwdAAuamF2YS51dGlsLmNvbmN1
cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9yJFdvcmtlcnEAfgBCcQB-AC1xAH4AGHEAfgAZc3EAfgAM
AgAAAz1wdAAQamF2YS5sYW5nLlRocmVhZHQAC1RocmVhZC5qYXZhcQB-AC1xAH4AGHEAfgAZc3IA
H2phdmEudXRpbC5Db2xsZWN0aW9ucyRFbXB0eUxpc3R6uBe0PKee3gIAAHhweAAAEJp3CAAAAAAA
AAAAeA
2021-07-29 07:31:16,850 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-7:ctx-167802d6 job-33329/job-33685 ctx-e8692fdb)
(logid:68ca6ba5) Publish async job-33685 complete on message bus
2021-07-29 07:31:16,850 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-7:ctx-167802d6 job-33329/job-33685 ctx-e8692fdb)
(logid:68ca6ba5) Wake up jobs related to job-33685
2021-07-29 07:31:16,850 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-7:ctx-167802d6 job-33329/job-33685 ctx-e8692fdb)
(logid:68ca6ba5) Update db status for job-33685
2021-07-29 07:31:16,850 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-7:ctx-167802d6 job-33329/job-33685 ctx-e8692fdb)
(logid:68ca6ba5) Wake up jobs joined with job-33685 and disjoin all subjobs
created from job- 33685
2021-07-29 07:31:16,853 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-7:ctx-167802d6 job-33329/job-33685) (logid:68ca6ba5) Done
with run of VM work job: com.cloud.vm.VmWorkStart for VM 1905, job origin:
33329
2021-07-29 07:31:16,853 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-7:ctx-167802d6 job-33329/job-33685) (logid:68ca6ba5) Done
executing com.cloud.vm.VmWorkStart for job-33685
2021-07-29 07:31:16,854 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-7:ctx-167802d6 job-33329/job-33685) (logid:68ca6ba5)
Remove job-33685 from job monitoring
2021-07-29 07:31:16,856 WARN [o.a.c.s.SecondaryStorageManagerImpl]
(secstorage-1:ctx-8c334da3) (logid:7d657b86) Exception while trying to start
secondary storage vm
com.cloud.utils.exception.CloudRuntimeException: Unable to start VM instance
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManage
rImpl.java:5507)
at jdk.internal.reflect.GeneratedMethodAccessor542.invoke(Unknown
Source)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Delegatin
gMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.jav
a:107)
at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManager
Impl.java:5669)
at
com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext
(AsyncJobManagerImpl.java:620)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedCo
ntextRunnable.java:48)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(Defa
ultManagedContext.java:55)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithCon
text(DefaultManagedContext.java:102)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithCont
ext(DefaultManagedContext.java:52)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedCont
extRunnable.java:45)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJob
ManagerImpl.java:568)
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.ThreadPoolExecutor.runWorker(ThreadPoolExecut
or.java:1128)
at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecu
tor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)
2021-07-29 07:31:16,856 INFO [o.a.c.s.SecondaryStorageManagerImpl]
(secstorage-1:ctx-8c334da3) (logid:7d657b86) Unable to start secondary
storage vm for standby capacity, vm id : 1905, will recycle it and start a
new one
2021-07-29 07:31:16,856 DEBUG [c.c.a.SecondaryStorageVmAlertAdapter]
(secstorage-1:ctx-8c334da3) (logid:7d657b86) received secondary storage vm
alert
2021-07-29 07:31:16,857 DEBUG [c.c.a.SecondaryStorageVmAlertAdapter]
(secstorage-1:ctx-8c334da3) (logid:7d657b86) Secondary Storage Vm creation
failure, zone: EMEA01
2021-07-29 07:31:16,857 WARN [c.c.a.AlertManagerImpl]
(secstorage-1:ctx-8c334da3) (logid:7d657b86) AlertType:: 19 | dataCenterId::
1 | podId:: null | clusterId:: null | message:: Secondary Storage Vm
creation failure. zone: EMEA01, error details: null
2021-07-29 07:31:16,859 INFO [o.a.c.s.PremiumSecondaryStorageManagerImpl]
(secstorage-1:ctx-8c334da3) (logid:7d657b86) Primary secondary storage is
not even started, wait until next turn
2021-07-29 07:31:16,866 DEBUG [o.a.c.s.SecondaryStorageManagerImpl]
(secstorage-1:ctx-98870ebc) (logid:c4cd27ad) Zone 1 is ready to launch
secondary storage VM"
Is there any workaround for this?
Thank you,
Cristian
