weizhouapache commented on issue #7053:
URL: https://github.com/apache/cloudstack/issues/7053#issuecomment-1372030371
> > can you share more logs, please ?
> > management log:
>
> ## 2023-01-05 17:52:11,528 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-98:ctx-00ddfb01 job-446/job-447) (logid:564609bc) Done with
run of VM work job: com.cloud.vm.VmWorkStart for VM 101, job origin: 446
> 2023-01-05 17:52:11,528 ERROR [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-98:ctx-00ddfb01 job-446/job-447) (logid:564609bc) Unable to
complete AsyncJobVO: {id:447, userId: 2, accountId: 2, instanceType: null,
instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
>
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAZXQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 26183377
3422727, completeMsid: null, lastUpdated: null, lastPolled: null, created: Thu
Jan 05 17:51:56 CST 2023, removed: null}, job
origin:446com.cloud.exception.InsufficientServerCapacityException: Unable to
create a deployment for VM instance {id: "101", name: "i-2-101-VM", uuid:
"60093c58-bba6-470e-a958-0d30e5507628", type="User"}Scope=interface
com.cloud.dc.DataCenter; id=1
> at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1140)
> at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5315)
> at jdk.internal.reflect.GeneratedMethodAccessor554.invoke(Unknown Source)
> at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.base/java.lang.reflect.Method.invoke(Method.java:566)
> at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
> at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5439)
> 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(ManagedContextRunnable.java:48)
> at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
> at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
> at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
> at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:45)
> at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.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(ThreadPoolExecutor.java:1128)
> at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
> at java.base/java.lang.Thread.run(Thread.java:829)
> 2023-01-05 17:52:11,541 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-98:ctx-00ddfb01 job-446/job-447) (logid:564609bc) Remove
job-447 from job monitoring
> 2023-01-05 17:52:11,554 DEBUG [c.c.v.UserVmManagerImpl]
(API-Job-Executor-117:ctx-f896976b job-446 ctx-c292f039) (logid:564609bc)
Destroying vm VM instance {id: "101", name: "i-2-101-VM", uuid:
"60093c58-bba6-470e-a958-0d30e5507628", type="User"} as it failed to create
> on Host with Id:12023-01-05 17:52:11,571 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-117:ctx-f896976b job-446 ctx-c292f039) (logid:564609bc) VM
instance {id: "101", name: "i-2-101-VM", uuid:
"60093c58-bba6-470e-a958-0d30e5507628", type="User"} state transited from
[Stopped] to [
> Error] with event [OperationFailedToError]. VM's original host: null, new
host: null, host before state transition: null2023-01-05 17:52:11,586 DEBUG
[c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-117:ctx-f896976b job-446
ctx-c292f039) (logid:564609bc) Updating resource Type = volume count for
Account = 2 Operation = decreasing Amount = 1
> 2023-01-05 17:52:11,595 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-117:ctx-f896976b job-446 ctx-c292f039) (logid:564609bc)
Updating resource Type = primary_storage count for Account = 2 Operation =
decreasing Amount = (20.00 GB) 21474836480
> 2023-01-05 17:52:11,614 WARN [c.c.a.AlertManagerImpl]
(API-Job-Executor-117:ctx-f896976b job-446 ctx-c292f039) (logid:564609bc)
alertType=[8] dataCenterId=[1] podId=[1] clusterId=[null] message=[Failed to
deploy Vm with Id: 101, on Host with Id: 1].
> 2023-01-05 17:52:11,621 WARN [c.c.a.AlertManagerImpl]
(API-Job-Executor-117:ctx-f896976b job-446 ctx-c292f039) (logid:564609bc) No
recipients set in global setting 'alert.email.addresses', skipping sending
alert with subject [Failed to deploy Vm with Id: 101, on Host w
> ith Id: 1] and content [Failed to deploy Vm with Id: 101, on Host with Id:
1].2023-01-05 17:52:11,622 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-117:ctx-f896976b job-446 ctx-c292f039) (logid:564609bc)
Updating resource Type = user_vm count for Account = 2 Operation = decreasing
Amount = 1
> 2023-01-05 17:52:11,630 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-117:ctx-f896976b job-446 ctx-c292f039) (logid:564609bc)
Updating resource Type = cpu count for Account = 2 Operation = decreasing
Amount = 1
> 2023-01-05 17:52:11,637 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-117:ctx-f896976b job-446 ctx-c292f039) (logid:564609bc)
Updating resource Type = memory count for Account = 2 Operation = decreasing
Amount = 512
> 2023-01-05 17:52:11,653 ERROR [c.c.a.ApiAsyncJobDispatcher]
(API-Job-Executor-117:ctx-f896976b job-446) (logid:564609bc) Unexpected
exception while executing
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin
> com.cloud.utils.exception.CloudRuntimeException: Unable to start a VM
[60093c58-bba6-470e-a958-0d30e5507628] due to [Unable to create a deployment
for VM instance {id: "101", name: "i-2-101-VM", uuid:
"60093c58-bba6-470e-a958-0d30e5507628", type="User"}].
> at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:803)
> at
org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:243)
> at
org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:214)
> at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:5311)
> at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:5161)
> at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:4788)
> at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:4777)
> 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.apache.cloudstack.network.contrail.management.EventUtils$EventInterceptor.invoke(EventUtils.java:107)
> at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)
> at
com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:52)
> at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)
> at
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
> at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
> at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215)
> at com.sun.proxy.$Proxy180.startVirtualMachine(Unknown Source)
> at
org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:714)
> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:163)
> at
com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:106)
> at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:620)
> at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:48)
> at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
> at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
> at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
> at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:45)
> at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.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(ThreadPoolExecutor.java:1128)
> at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
> at java.base/java.lang.Thread.run(Thread.java:829)
> Caused by: com.cloud.exception.InsufficientServerCapacityException: Unable
to create a deployment for VM instance {id: "101", name: "i-2-101-VM", uuid:
"60093c58-bba6-470e-a958-0d30e5507628", type="User"}Scope=interface
com.cloud.dc.DataCenter; id=1
> at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1140)
> at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5315)
> at jdk.internal.reflect.GeneratedMethodAccessor554.invoke(Unknown Source)
> ... 17 more
> 2023-01-05 17:52:11,664 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-117:ctx-f896976b job-446) (logid:564609bc) Remove job-446
from job monitoring
> 2023-01-05 17:52:11,768 DEBUG [c.c.a.ApiServlet]
(qtp1747352992-8705:ctx-d2189185) (logid:b61b54a5) ===START=== 192.168.0.102 --
GET
jobId=564609bc-a5e0-43eb-a1a9-45f5513d3ee0&command=queryAsyncJobResult&response=json
> 2023-01-05 17:52:11,772 DEBUG [c.c.a.ApiServer]
(qtp1747352992-8705:ctx-d2189185 ctx-cbaabce4) (logid:b61b54a5) CIDRs from
which account 'Acct[2217c707-8817-11ed-9cb1-04421a1ae40d-admin] -- Account
{"id": 2, "name": "admin", "uuid": "2217c707-8817-11ed-9cb1-04421a1ae40d
> "}' is allowed to perform API calls: 0.0.0.0/0,::/0
> agent log: 2023-01-05 17:52:04,529 DEBUG
[resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-2:null)
(logid:564609bc) Trying to connect to 169.254.236.18 2023-01-05 17:52:05,532
DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:)
Executing: /usr/share/cloudstack-common/scripts/vm/network/security_group.py
get_rule_logs_for_vms 2023-01-05 17:52:05,534 DEBUG
[kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Executing
while with timeout : 1800000 2023-01-05 17:52:05,624 DEBUG
[kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Execution
is successful. 2023-01-05 17:52:05,625 DEBUG [kvm.resource.LibvirtConnection]
(UgentTask-5:null) (logid:) Looking for libvirtd connection at: qemu:///system
2023-01-05 17:52:05,641 DEBUG [cloud.agent.Agent] (UgentTask-5:null) (logid:)
Sending ping: Seq 1-438: { Cmd , MgmtId: -1, via: 1, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.PingRoutingWithNwGroupsCommand":{"newGroupState
s":{},"_hostVmStateReport":{"v-88-VM":{"state":"
PowerOn","host":"cluster13"},"r-99-VM":{"state":"PowerOn","host":"cluster13"},"s-89-VM":{"state":"PowerOn","host":"cluster13"}},"_gatewayAccessible":"true","_vnetAccessible":"true","hostType":"Routing","hostId":"1","wait":"0","bypassHostMaintenance":"false"}}]
}2023-01-05 17:52:05,709 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
(logid:05ee669b) Received response: Seq 1-438: { Ans: , MgmtId:
261833773422727, via: 1, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.PingAnswer":{"_command":{"hostType":"Routing","hostId":"1","
wait":"0","bypassHostMaintenance":"false"},"result":"true","wait":"0","bypassHostMaintenance":"false"}}]
}2023-01-05 17:52:08,514 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-2:null) (logid:564609bc) Processing command:
com.cloud.agent.api.check.CheckSshCommand 2023-01-05 17:52:08,514 DEBUG
[resource.wrapper.LibvirtOvsVpcRoutingPolicyConfigCommandWrapper]
(agentRequest-Handler-2:null) (logid:564609bc) Ping com
mand port, 169.254.236.18:3922 2023-01-05 17:52:08,514 DEBUG
[resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-2:null)
(logid:564609bc) Trying to connect to 169.254.236.18 2023-01-05 17:52:08,515
DEBUG [resource.wrapper.LibvirtOvsVpcRoutingPolicyConfigCommandWrapper]
(agentRequest-Handler-2:null) (logid:564609bc) Ping command port succeeded for
vm r-99-VM 2023-01-05 17:52:08,515 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-2:null) (logid:564609bc) Processing command:
com.cloud.agent.api.GetDomRVersionCmd 2023-01-05 17:52:08,515 DEBUG
[kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null)
(logid:564609bc) Executing:
/usr/share/cloudstack-common/scripts/network/domr/router_proxy.sh
get_template_version.sh 169.254.236.18 2023-01-05 17:52:08,517 DEBUG
[kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null)
(logid:564609bc) Executing while with timeout : 1800000 2023-01-05 17:52:08,598
DEBUG [kvm.resource.LibvirtComputingResource] (age
ntRequest-Handler-2:null) (logid:564609bc) Exit value is 255 2023-01-05
17:52:08,599 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-2:null) (logid:564609bc) 2023-01-05 17:52:08,599 DEBUG
[kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null)
(logid:564609bc) Executing script in VR: get_template_version.sh 2023-01-05
17:52:08,613 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null)
(logid:564609bc) Seq 1-4745668107341661094: { Ans: , MgmtId: 261833773422727,
via: 1, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StartAnswer":{"vm":{"id":"99","name":"r-99-VM","state":"Star
ting","type":"DomainRouter","cpus":"1","minSpeed":"500","maxSpeed":"500","minRam":"(256.00
MB) 268435456","maxRam":"(256.00 MB) 268435456","arch":"x86_64","os":"Debian
GNU/Linux 5.0 (64-bit)","platformEmulator":"Debian GNU/Linux 5","bootArgs":"
template=domP name=r-99-VM
authorized_key=c3NoLXJzYSBBQUFBQjNOemFDMXljMkVBQUFBREFRQUJBQUFCZ1FEZmcxeUV5b0VONWtOZEd4SVcwYlJUWHN1RFJSd2ZBTDBhN
Hdpa2Y5QXhrdWZTSEJhMnhTSmJmWm5mcXpvN1FmNDBlempzcm1UTDE4bzZyT1NkQUE4cFN1NHpXcTh0Rzg1VWszSDA5bkkrdSs4eGtlNlFvckhaK3JUZVVjTFh5WU1wSGd1UEJTeUxZSGhMelllMlJSRXRVRU5lWW9DbndCT0hlbmVsZTNWTnZrM3gwR2dpUTdpTE41RXpqQlpVSTgzMnYxcDNXcHVNQnF3ZEhlcVdxdUNmMEdXNGlUc0gzejZDZXhXakhXc21Fc3VEbTBNU3ZrWEszR2V2RWtUZytiL0hrRXBpV2NOMnBQb3ErcGU5N2dLV3I5UW40U2x6ZnUyZHZpZXdQdWJzSFBiMGFzeHdWRHB3eVp0M1cwMktBaHhSVEtZZkxnVWFJSGZnZWFFVzRLUDZpQ3V5bVdoM3lzYVBvUVE3S1JJd3BjR003STVFQmEvV1hybDlkcU14K2pLV3A4MjJOQ0ZlUmNGazFPbUtBNTY2ci9DLzdvUTZLc1VVWTEzQVByenNMN09NaUdMdXYzaFlhNlBkN0FHdnd5SEcvVE42dml3QlMrVXhJMDFHaktxL0V2UTZPaWhQanBTVXpWU3ZZdnRkRCt5TDFDUXVSQ1RROWtnR2lRTFl6RXM9IGNsb3VkQGNsdXN0ZXIxMwo=
eth0ip=192.168.0.78 eth0mask=255.255.255.0 gateway=192.168.0.200
domain=cs1cloud.internal cidrsize=24 dhcprange=192.168.0.1
eth1ip=169.254.236.18 eth1mask=255.255.0.0 type=dhcpsrvr disable_rp_filter=true
dns1=8.8.8.8 exposedns=true
baremetalnotificationsecuritykey=dQVh_AIeRj6Bnqmy4Yk5h2PqeKd6STcTareyLEPQImE9J56kGuDrrNJfEHfi_0iPny1j
LzntlTxsTHLpTYOzfg
baremetalnotificationapikey=yQ6xRwhUH7pN7LmCTn5-Jp9saoc3t6vdrre3VSqb4basX1ccm9EN-iSC17g7HuBQiN2Ow03jYEvLSy7spt1h1A
host=192.168.0.13
port=8080","enableHA":"true","limitCpuUse":"false","enableDynamicallyScaleVm":"false","vncPassword":"Dmz6dCAEg-7xINbmS8HlIg","vncAddr":"192.168.0.13","params":{},"uuid":"4fcea489-51f8-4bd9-baef-65dc22828a94","enterHardwareSetup":"false","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"68bbe57a-a958-430f-8a97-f3a4cc2d4b4e","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"9c23d00b-a619-4842-a7d1-045727e46f0e","name":"cluster13-local-9c23d00b","id":"1","poolType":"Filesystem","host":"192.168.0.13","path":"/var/lib/libvirt/images","port":"0","url":"Filesystem://192.168.0.13/var/lib/libvirt/images/?ROLE=Primary&STOREUUID=9c23d00b-a619-4842-a7d1-045727e46f0e","isManaged":"false"}},"name":"ROOT-99","size":"(3.91
GB) 4194304000","path":"68bbe57a-a958-430f-8a97-f3a4cc2
d4b4e","volumeId":"80","vmName":"r-99-VM","accountId":"1","format":"QCOW2","provisioningType":"THIN","poolId":"1","id":"80","deviceId":"0","bytesReadRate":"(0
bytes) 0","bytesWriteRate":"(0 bytes) 0","iopsReadRate":"(0 bytes)
0","iopsWriteRate":"(0 bytes)
0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"}},"diskSeq":"0","path":"68bbe57a-a958-430f-8a97-f3a4cc2d4b4e","type":"ROOT","_details":{"storageHost":"192.168.0.13","managed":"false","storagePort":"0","storage.pool.disk.wait":"60","volumeSize":"(3.91
GB)
4194304000"}}],"nics":[{"deviceId":"0","networkRateMbps":"200","defaultNic":"true","pxeDisable":"true","nicUuid":"599503a1-23c4-436e-8bc9-cbf0bc3bda53","details":{"MacLearning":"false","MacAddressChanges":"true","PromiscuousMode":"false","ForgedTransmits":"true"},"dpdkEnabled":"false","uuid":"808f347a-c4ec-45fb-bd7d-73b774fecc96","ip":"192.168.0.78","netmask":"255.255.255.0","gateway":"192.168.0.200","mac":"1e:00:34:00:00:14","dns1":"8.8.8.8","broadcastType"
:"Native","type":"Guest","broadcastUri":"vlan://untagged","isSecurityGroupEnabled":"false"},{"deviceId":"1","networkRateMbps":"-1","defaultNic":"false","pxeDisable":"true","nicUuid":"88248332-e7de-47f4-8b2c-c339fb0debe6","details":{"MacLearning":"false","MacAddressChanges":"true","PromiscuousMode":"false","ForgedTransmits":"true"},"dpdkEnabled":"false","uuid":"c529c6ad-fc5f-4026-b91a-51514ee1e0f4","ip":"169.254.236.18","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:ec:12","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":"false"}],"vcpuMaxLimit":"1","configDriveLocation":"SECONDARY","guestOsDetails":{},"extraConfig":{}},"result":"true","wait":"0","bypassHostMaintenance":"false"}},{"com.cloud.agent.api.check.CheckSshAnswer":{"result":"true","wait":"0","bypassHostMaintenance":"false"}},{"com.cloud.agent.api.GetDomRVersionAnswer":{"result":"false","details":"GetDomRVersionCmd
failed","wait":"0","bypassHostMaintenance":"false"}},{"com.cloud.agent.
api.Answer":{"result":"false","details":"Stopped by previous
failure","wait":"0","bypassHostMaintenance":"false"}},{"com.cloud.agent.api.Answer":{"result":"false","details":"Stopped
by previous
failure","wait":"0","bypassHostMaintenance":"false"}},{"com.cloud.agent.api.Answer":{"result":"false","details":"Stopped
by previous
failure","wait":"0","bypassHostMaintenance":"false"}},{"com.cloud.agent.api.Answer":{"result":"false","details":"Stopped
by previous failure","wait":"0","bypassHostMaintenance":"false"}}] }2023-01-05
17:52:08,724 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:null)
(logid:564609bc) Request:Seq 1-4745668107341661096: { Cmd , MgmtId:
261833773422727, via: 1, Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":"false","checkBeforeClean
up":"false","controlIp":"169.254.144.182","forceStop":"false","vlanToPersistenceMap":{"untagged":"true"},"volumesToDisconnect":[],"vmName":"r-99-VM","executeInSequence":"false","wait":"0","bypassHostMaintenance"
:"false"}}] }2023-01-05 17:52:08,725 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-5:null) (logid:564609bc) Processing command:
com.cloud.agent.api.StopCommand 2023-01-05 17:52:08,725 DEBUG
[kvm.resource.LibvirtConnection] (agentRequest-Handler-5:null) (logid:564609bc)
Looking for libvirtd connection at: qemu:///system 2023-01-05 17:52:08,746
DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-5:null)
(logid:564609bc) Executing:
/usr/share/cloudstack-common/scripts/vm/network/security_group.py
destroy_network_rules_for_vm --vmname r-99-VM --vif vnet52 2023-01-05
17:52:08,747 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-5:null) (logid:564609bc) Executing while with timeout :
1800000 2023-01-05 17:52:08,841 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-5:null) (logid:564609bc) Execution is successful.
2023-01-05 17:52:08,842 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-5:null) (logid:564609bc) Cleani
ng the metadata of vm snapshots of vm r-99-VM 2023-01-05 17:52:08,843 DEBUG
[kvm.resource.LibvirtComputingResource] (agentRequest-Handler-5:null)
(logid:564609bc) Try to stop the vm at first 2023-01-05 17:52:10,951 DEBUG
[kvm.resource.LibvirtComputingResource] (agentRequest-Handler-5:null)
(logid:564609bc) successfully shut down vm r-99-VM 2023-01-05 17:52:10,951 WARN
[kvm.resource.LibvirtKvmAgentHook] (agentRequest-Handler-5:null)
(logid:564609bc) Groovy script
'/etc/cloudstack/agent/hooks/libvirt-vm-state-change.groovy' is not available.
Transformations will not be applied. 2023-01-05 17:52:10,951 WARN
[kvm.resource.LibvirtKvmAgentHook] (agentRequest-Handler-5:null)
(logid:564609bc) Groovy scripting engine is not initialized. Data
transformation skipped. 2023-01-05 17:52:10,951 DEBUG
[kvm.storage.KVMStoragePoolManager] (agentRequest-Handler-5:null)
(logid:564609bc) Disconnect physical disk by path:
/var/lib/libvirt/images/68bbe57a-a958-430f-8a97-f3a4cc2d4b4e 2023-01-05
17:52:10,95
1 DEBUG [kvm.storage.StorPoolStorageAdaptor] (agentRequest-Handler-5:null)
(logid:564609bc) disconnectPhysicalDiskByPath:
localPath=/var/lib/libvirt/images/68bbe57a-a958-430f-8a97-f3a4cc2d4b4e
2023-01-05 17:52:10,951 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-5:null) (logid:564609bc) Unable to clean up disk with
null path (perhaps empty cdrom drive):
>
> 2023-01-05 17:52:10,951 DEBUG [utils.script.Script]
(agentRequest-Handler-5:null) (logid:564609bc) Executing: /bin/bash -c ls
/sys/class/net/cloudbr0 2023-01-05 17:52:10,953 DEBUG [utils.script.Script]
(agentRequest-Handler-5:null) (logid:564609bc) Executing while with timeout :
3600000 2023-01-05 17:52:10,957 DEBUG [utils.script.Script]
(agentRequest-Handler-5:null) (logid:564609bc) Execution is successful.
2023-01-05 17:52:10,958 DEBUG [utils.script.Script]
(agentRequest-Handler-5:null) (logid:564609bc) Executing: /bin/bash -c ls
/sys/class/net/cloudbr0/brif | tr ' ' ' ' 2023-01-05 17:52:10,960 DEBUG
[utils.script.Script] (agentRequest-Handler-5:null) (logid:564609bc) Executing
while with timeout : 3600000 2023-01-05 17:52:10,964 DEBUG
[utils.script.Script] (agentRequest-Handler-5:null) (logid:564609bc) Execution
is successful. 2023-01-05 17:52:10,965 DEBUG [utils.script.Script]
(agentRequest-Handler-5:null) (logid:564609bc) Executing: /bin/bash -c ls
/sys/class/net/cloud0 202
3-01-05 17:52:10,966 DEBUG [utils.script.Script] (agentRequest-Handler-5:null)
(logid:564609bc) Executing while with timeout : 3600000 2023-01-05 17:52:10,969
DEBUG [utils.script.Script] (agentRequest-Handler-5:null) (logid:564609bc)
Execution is successful. 2023-01-05 17:52:10,969 DEBUG [utils.script.Script]
(agentRequest-Handler-5:null) (logid:564609bc) Executing: /bin/bash -c ls
/sys/class/net/cloud0/brif | tr ' ' ' ' 2023-01-05 17:52:10,970 DEBUG
[utils.script.Script] (agentRequest-Handler-5:null) (logid:564609bc) Executing
while with timeout : 3600000 2023-01-05 17:52:10,974 DEBUG
[utils.script.Script] (agentRequest-Handler-5:null) (logid:564609bc) Execution
is successful. 2023-01-05 17:52:10,978 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-5:null) (logid:564609bc) Seq 1-4745668107341661096: {
Ans: , MgmtId: 261833773422727, via: 1, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StopAnswer":{"result":"true","wait":"0","bypassHostMaintenan
ce":"false"}}] }2023-01-05 17:52:10,998
DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:564609bc)
Request:Seq 1-4745668107341661097: { Cmd , MgmtId: 261833773422727, via: 1,
Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":"false","checkBeforeClean
up":"false","controlIp":"169.254.144.182","forceStop":"false","vlanToPersistenceMap":{"untagged":"true"},"volumesToDisconnect":[],"vmName":"r-99-VM","executeInSequence":"false","wait":"0","bypassHostMaintenance":"false"}}]
}2023-01-05 17:52:10,998 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-1:null) (logid:564609bc) Processing command:
com.cloud.agent.api.StopCommand 2023-01-05 17:52:10,998 DEBUG
[kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:564609bc)
Looking for libvirtd connection at: qemu:///system 2023-01-05 17:52:11,011
DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null)
(logid:564609bc) Can not find KVM connection for Instance: r-99-VM, continuing.
2023-01-05 17:52:11,011 DEBUG [kvm.resource.
LibvirtConnection] (agentRequest-Handler-1:null) (logid:564609bc) Looking for
libvirtd connection at: lxc:/// 2023-01-05 17:52:11,011 INFO
[kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:564609bc)
No existing libvirtd connection found. Opening a new one 2023-01-05
17:52:11,013 DEBUG [kvm.resource.LibvirtConnection]
(agentRequest-Handler-1:null) (logid:564609bc) Can not find LXC connection for
Instance: r-99-VM, continuing. 2023-01-05 17:52:11,013 WARN
[kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:564609bc)
Can not find a connection for Instance r-99-VM. Assuming the default
connection. 2023-01-05 17:52:11,013 DEBUG [kvm.resource.LibvirtConnection]
(agentRequest-Handler-1:null) (logid:564609bc) Looking for libvirtd connection
at: qemu:///system 2023-01-05 17:52:11,026 DEBUG
[kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null)
(logid:564609bc) Failed to get dom xml: org.libvirt.LibvirtException: Domain
not found: no domain
with matching name 'r-99-VM' 2023-01-05 17:52:11,026 DEBUG
[kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null)
(logid:564609bc) Failed to get dom xml: org.libvirt.LibvirtException: Domain
not found: no domain with matching name 'r-99-VM' 2023-01-05 17:52:11,026 DEBUG
[kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null)
(logid:564609bc) Failed to get dom xml: org.libvirt.LibvirtException: Domain
not found: no domain with matching name 'r-99-VM' 2023-01-05 17:52:11,026 DEBUG
[kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null)
(logid:564609bc) Executing:
/usr/share/cloudstack-common/scripts/vm/network/security_group.py
destroy_network_rules_for_vm --vmname r-99-VM 2023-01-05 17:52:11,027 DEBUG
[kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null)
(logid:564609bc) Executing while with timeout : 1800000 2023-01-05 17:52:11,124
DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null)
(logid:564609bc)
Execution is successful. 2023-01-05 17:52:11,125 DEBUG
[kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null)
(logid:564609bc) Failed to get vm :Domain not found: no domain with matching
name 'r-99-VM' 2023-01-05 17:52:11,125 DEBUG
[kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null)
(logid:564609bc) Try to stop the vm at first 2023-01-05 17:52:11,126 DEBUG
[kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null)
(logid:564609bc) VM r-99-VM doesn't exist, no need to stop it 2023-01-05
17:52:11,126 WARN [kvm.resource.LibvirtKvmAgentHook]
(agentRequest-Handler-1:null) (logid:564609bc) Groovy script
'/etc/cloudstack/agent/hooks/libvirt-vm-state-change.groovy' is not available.
Transformations will not be applied. 2023-01-05 17:52:11,126 WARN
[kvm.resource.LibvirtKvmAgentHook] (agentRequest-Handler-1:null)
(logid:564609bc) Groovy scripting engine is not initialized. Data
transformation skipped. 2023-01-05 17:52:11,126 DEBUG [cloud.agent.Agent
] (agentRequest-Handler-1:null) (logid:564609bc) Seq 1-4745668107341661097: {
Ans: , MgmtId: 261833773422727, via: 1, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StopAnswer":{"result":"true","wait":"0","bypassHostMaintenan
ce":"false"}}] }2023-01-05 17:52:11,239 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-4:null) (logid:564609bc) Request:Seq
1-4745668107341661098: { Cmd , MgmtId: 261833773422727, via: 1, Ver: v1, Flags:
100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":"false","checkBeforeClean
up":"false","forceStop":"false","vlanToPersistenceMap":{"untagged":"true"},"volumesToDisconnect":[],"vmName":"i-2-101-VM","executeInSequence":"false","wait":"0","bypassHostMaintenance":"false"}}]
}2023-01-05 17:52:11,239 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-4:null) (logid:564609bc) Processing command:
com.cloud.agent.api.StopCommand 2023-01-05 17:52:11,239 DEBUG
[kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:564609bc)
Looking for libvirtd connection a
t: qemu:///system 2023-01-05 17:52:11,252 DEBUG
[kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:564609bc)
Can not find KVM connection for Instance: i-2-101-VM, continuing. 2023-01-05
17:52:11,252 DEBUG [kvm.resource.LibvirtConnection]
(agentRequest-Handler-4:null) (logid:564609bc) Looking for libvirtd connection
at: lxc:/// 2023-01-05 17:52:11,252 INFO [kvm.resource.LibvirtConnection]
(agentRequest-Handler-4:null) (logid:564609bc) No existing libvirtd connection
found. Opening a new one 2023-01-05 17:52:11,253 DEBUG
[kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:564609bc)
Can not find LXC connection for Instance: i-2-101-VM, continuing. 2023-01-05
17:52:11,253 WARN [kvm.resource.LibvirtConnection]
(agentRequest-Handler-4:null) (logid:564609bc) Can not find a connection for
Instance i-2-101-VM. Assuming the default connection. 2023-01-05 17:52:11,253
DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null)
(logid:564609bc) Look
ing for libvirtd connection at: qemu:///system 2023-01-05 17:52:11,265 DEBUG
[kvm.resource.LibvirtComputingResource] (agentRequest-Handler-4:null)
(logid:564609bc) Failed to get dom xml: org.libvirt.LibvirtException: Domain
not found: no domain with matching name 'i-2-101-VM' 2023-01-05 17:52:11,266
DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-4:null)
(logid:564609bc) Failed to get dom xml: org.libvirt.LibvirtException: Domain
not found: no domain with matching name 'i-2-101-VM' 2023-01-05 17:52:11,266
DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-4:null)
(logid:564609bc) Failed to get dom xml: org.libvirt.LibvirtException: Domain
not found: no domain with matching name 'i-2-101-VM' 2023-01-05 17:52:11,266
DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-4:null)
(logid:564609bc) Executing:
/usr/share/cloudstack-common/scripts/vm/network/security_group.py
destroy_network_rules_for_vm --vmname i-2-101-VM 2023-01-05 17:52:
11,267 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-4:null) (logid:564609bc) Executing while with timeout :
1800000 2023-01-05 17:52:11,448 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-4:null) (logid:564609bc) Execution is successful.
2023-01-05 17:52:11,449 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-4:null) (logid:564609bc) ebtables: No chain/target/match
by that name ebtables: No chain/target/match by that name ebtables: No
chain/target/match by that name ebtables: No chain/target/match by that name
ebtables: No chain/target/match by that name ebtables: No chain/target/match by
that name iptables: No chain/target/match by that name. iptables: No
chain/target/match by that name. iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name. iptables: No chain/target/match
by that name. iptables: No chain/target/match by that name. ipset v7.1: The set
with the given name does not exis
t
>
> 2023-01-05 17:52:11,450 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-4:null) (logid:564609bc) Failed to get vm :Domain not
found: no domain with matching name 'i-2-101-VM' 2023-01-05 17:52:11,450 DEBUG
[kvm.resource.LibvirtComputingResource] (agentRequest-Handler-4:null)
(logid:564609bc) Try to stop the vm at first 2023-01-05 17:52:11,450 DEBUG
[kvm.resource.LibvirtComputingResource] (agentRequest-Handler-4:null)
(logid:564609bc) VM i-2-101-VM doesn't exist, no need to stop it 2023-01-05
17:52:11,450 WARN [kvm.resource.LibvirtKvmAgentHook]
(agentRequest-Handler-4:null) (logid:564609bc) Groovy script
'/etc/cloudstack/agent/hooks/libvirt-vm-state-change.groovy' is not available.
Transformations will not be applied. 2023-01-05 17:52:11,451 WARN
[kvm.resource.LibvirtKvmAgentHook] (agentRequest-Handler-4:null)
(logid:564609bc) Groovy scripting engine is not initialized. Data
transformation skipped. 2023-01-05 17:52:11,451 DEBUG [cloud.agent.Agent]
(agentRequest
-Handler-4:null) (logid:564609bc) Seq 1-4745668107341661098: { Ans: , MgmtId:
261833773422727, via: 1, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StopAnswer":{"result":"true","wait":"0","bypassHostMaintenan
ce":"false"}}] }2023-01-05 17:52:33,939 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-3:null) (logid:d8ff1a24) Processing command:
com.cloud.agent.api.GetStorageStatsCommand 2023-01-05 17:52:33,940 INFO
[kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null)
(logid:d8ff1a24) Trying to fetch storage pool
9c23d00b-a619-4842-a7d1-045727e46f0e from libvirt
@fangyi1008
there was an issue while start the VR.
```
2023-01-05 17:52:08,515 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-2:null) (logid:564609bc) Executing:
/usr/share/cloudstack-common/scripts/network/domr/router_proxy.sh
get_template_version.sh 169.254.236.18
2023-01-05 17:52:08,517 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-2:null) (logid:564609bc) Executing while with timeout :
1800000
2023-01-05 17:52:08,598 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-2:null) (logid:564609bc) Exit value is 255
```
can you check if the VR is created from correct template ?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
