[
https://issues.apache.org/jira/browse/CLOUDSTACK-10028?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Rohit Yadav reassigned CLOUDSTACK-10028:
----------------------------------------
Assignee: Rohit Yadav
> Rebooting router fails
> ----------------------
>
> Key: CLOUDSTACK-10028
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-10028
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the
> default.)
> Components: Virtual Router
> Affects Versions: 4.11.0.0
> Reporter: Boris Stoyanov
> Assignee: Rohit Yadav
>
> Few tests report errors on starting/restarting a router:
> test_01_nic Error 193.93 test_nic.py
> test_reboot_router Error 238.47 test_network.py
> test_03_vpc_privategw_restart_vpc_cleanup
> Here's the log from management
> {code}
> 2017-08-03 08:39:21,485 INFO [c.c.v.VirtualMachineManagerImpl]
> (AgentManager-Handler-11:null) (logid:) There is pending job or HA tasks
> working on the VM. vm id: 26, postpone power-change report by resetting
> power-change counters
> 2017-08-03 08:39:21,494 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-11:null) (logid:) Done with process of VM state report.
> host: 2
> 2017-08-03 08:39:22,989 DEBUG [c.c.a.ApiServlet]
> (catalina-exec-25:ctx-9de4b3c2) (logid:9e34d539) ===START=== 10.1.0.1 -- GET
>
> signature=GW5N4FsQQmEwb88LLMgUbiAJKVA%3D&apiKey=LIN6rqXuaJwMPfGYFh13qDwYz5VNNz1J2J6qIOWcd3oLQOq0WtD4CwRundBL6rzXToa3lQOC_vKjI3nkHtiD8Q&command=queryAsyncJobResult&response=json&jobid=79f83157-5dbb-4d3e-afd0-90306550030d
> 2017-08-03 08:39:23,005 DEBUG [c.c.a.ApiServlet]
> (catalina-exec-25:ctx-9de4b3c2 ctx-3955671b ctx-82b0f609) (logid:9e34d539)
> ===END=== 10.1.0.1 -- GET
> signature=GW5N4FsQQmEwb88LLMgUbiAJKVA%3D&apiKey=LIN6rqXuaJwMPfGYFh13qDwYz5VNNz1J2J6qIOWcd3oLQOq0WtD4CwRundBL6rzXToa3lQOC_vKjI3nkHtiD8Q&command=queryAsyncJobResult&response=json&jobid=79f83157-5dbb-4d3e-afd0-90306550030d
> 2017-08-03 08:39:23,518 DEBUG [c.c.a.t.Request]
> (AgentManager-Handler-15:null) (logid:) Seq 2-2966746254530314637:
> Processing: { Ans: , MgmtId: 7589375051554, via: 2, Ver: v1, Flags: 110,
> [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":26,"name":"r-26-VM","type":"DomainRouter","cpus":1,"minSpeed":250,"maxSpeed":500,"minRam":268435456,"maxRam":268435456,"arch":"x86_64","os":"Debian
> GNU/Linux 5.0 (64-bit)","platformEmulator":"Debian GNU/Linux 5","bootArgs":"
> vpccidr=10.0.1.0/24 domain=cs20cloud.internal dns1=8.8.8.8 dns2=8.8.4.4
> privategateway=10.0.3.100 template=domP name=r-26-VM eth0ip=169.254.2.154
> eth0mask=255.255.0.0 type=vpcrouter disable_rp_filter=true
> baremetalnotificationsecuritykey=FiAIoemfwpWCOGXSL9LkNkpkHN3Tg0a2uFsd65sZR-3YbILIk5QvtBykdEAqjqIHFyv15jLtyl2XwNqMJwYuyA
>
> baremetalnotificationapikey=7xDDCgrtLsx-yJXbsgF78xrImLPW7Pbit__g33ANzDPDdlpxtnMqamTk08teVDvvp-0m3rwIQSWait8Lc99y_g
> host=10.2.2.42
> port=8080","enableHA":true,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"GWzMbEzuzvbnc1RGLYFPwg","vncAddr":"10.2.2.45","params":{"cpuOvercommitRatio":"2.0","memoryOvercommitRatio":"1.0"},"uuid":"dde05785-343b-425e-b700-40320b71421f","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"df8ebe6a-bf69-4de8-ba70-f05b75b36309","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"81433667-8d42-39db-8e1b-e74d2167dcc0","id":1,"poolType":"NetworkFilesystem","host":"10.2.0.16","path":"/acs/primary/trl-796-k-cs411-bstoyanov/trl-796-k-cs411-bstoyanov-kvm-pri1","port":2049,"url":"NetworkFilesystem://10.2.0.16/acs/primary/trl-796-k-cs411-bstoyanov/trl-796-k-cs411-bstoyanov-kvm-pri1/?ROLE=Primary&STOREUUID=81433667-8d42-39db-8e1b-e74d2167dcc0","isManaged":false}},"name":"ROOT-26","size":349752832,"path":"df8ebe6a-bf69-4de8-ba70-f05b75b36309","volumeId":28,"vmName":"r-26-VM","accountId":32,"format":"QCOW2","provisioningType":"THIN","id":28,"deviceId":0,"bytesReadRate":0,"bytesWriteRate":0,"iopsReadRate":0,"iopsWriteRate":0,"hypervisorType":"KVM"}},"diskSeq":0,"path":"df8ebe6a-bf69-4de8-ba70-f05b75b36309","type":"ROOT","_details":{"storageHost":"10.2.0.16","managed":"false","storagePort":"2049","volumeSize":"349752832"}}],"nics":[{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"pxeDisable":true,"nicUuid":"e240a815-7cb9-45f3-b4fb-684b54ac7682","uuid":"1b67c5d8-fa83-41ca-a20d-2ecb0c0db0d1","ip":"169.254.2.154","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:02:9a","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false}],"guestOsDetails":{}},"result":true,"wait":0}},{"com.cloud.agent.api.check.CheckSshAnswer":{"result":true,"wait":0}},{"com.cloud.agent.api.GetDomRVersionAnswer":{"templateVersion":"Cloudstack
> Release 4.10.0 Wed Jun 14 04:42:21 UTC
> 2017","scriptsVersion":"d3e3b82cd825b0cb33c1d7f8db3f8a3a\n","result":true,"details":"Cloudstack
> Release 4.10.0 Wed Jun 14 04:42:21 UTC
> 2017&d3e3b82cd825b0cb33c1d7f8db3f8a3a\n","wait":0}},{"com.cloud.agent.api.PlugNicAnswer":{"result":true,"details":"success","wait":0}},{"com.cloud.agent.api.routing.GroupAnswer":{"results":["null
> - success: null","null - success: [INFO] update_config.py :: Processing
> incoming file => ip_associations.json\n[INFO] Processing JSON file
> ip_associations.json\n"],"result":true,"wait":0}},{"com.cloud.agent.api.Answer":{"result":true,"details":"Nothing
> to
> do","wait":0}},{"com.cloud.agent.api.PlugNicAnswer":{"result":true,"details":"success","wait":0}},{"com.cloud.agent.api.routing.GroupAnswer":{"results":["null
> - success: null","null - success: [INFO] update_config.py :: Processing
> incoming file => ip_associations.json\n[INFO] Processing JSON file
> ip_associations.json\n"],"result":true,"wait":0}},{"com.cloud.agent.api.routing.GroupAnswer":{"results":["null
> - success: null","null - success: [INFO] update_config.py :: Processing
> incoming file => network_acl.json\n[INFO] Processing JSON file
> network_acl.json\n"],"result":true,"wait":0}},{"com.cloud.agent.api.PlugNicAnswer":{"result":true,"details":"success","wait":0}},{"com.cloud.agent.api.routing.GroupAnswer":{"results":["null
> - success: null","null - success: [INFO] update_config.py :: No GuestNetwork
> configured yet. Configuring first one now.\n[INFO] Processing JSON file
> guest_network.json\n"],"result":true,"wait":0}},{"com.cloud.agent.api.routing.GroupAnswer":{"results":["null
> - success: null","null - success: [INFO] update_config.py :: Processing
> incoming file => static_routes.json\n[INFO] Processing JSON file
> static_routes.json\n"],"result":true,"wait":0}},{"com.cloud.agent.api.Answer":{"result":true,"details":"Command
> aggregation
> started","wait":0}},{"com.cloud.agent.api.Answer":{"result":true,"details":"Command
> aggregation
> finished","wait":0}},{"com.cloud.agent.api.Answer":{"result":true,"details":"Command
> aggregation
> started","wait":0}},{"com.cloud.agent.api.Answer":{"result":true,"wait":0}},{"com.cloud.agent.api.Answer":{"result":true,"wait":0}},{"com.cloud.agent.api.Answer":{"result":true,"wait":0}},{"com.cloud.agent.api.Answer":{"result":true,"wait":0}},{"com.cloud.agent.api.Answer":{"result":true,"wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"process
> hasn't
> exited","wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"Stopped
> by previous failure","wait":0}}] }
> 2017-08-03 08:39:23,518 DEBUG [c.c.a.m.AgentAttache]
> (AgentManager-Handler-15:null) (logid:) Seq 2-2966746254530314637: No more
> commands found
> 2017-08-03 08:39:23,518 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302 ctx-f68714cb)
> (logid:79f83157) Seq 2-2966746254530314637: Received: { Ans: , MgmtId:
> 7589375051554, via: 2(trl-796-k-cs411-bstoyanov-kvm2), Ver: v1, Flags: 110, {
> StartAnswer, CheckSshAnswer, GetDomRVersionAnswer, PlugNicAnswer,
> GroupAnswer, Answer, PlugNicAnswer, GroupAnswer, GroupAnswer, PlugNicAnswer,
> GroupAnswer, GroupAnswer, Answer, Answer, Answer, Answer, Answer, Answer,
> Answer, Answer, Answer, Answer } }
> 2017-08-03 08:39:23,525 WARN [o.a.c.alerts]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302 ctx-f68714cb)
> (logid:79f83157) AlertType:: 9 | dataCenterId:: 1 | podId:: 1 | clusterId::
> null | message:: Command: com.cloud.agent.api.Command failed while starting
> virtual router
> 2017-08-03 08:39:23,532 ERROR [c.c.n.r.VirtualNetworkApplianceManagerImpl]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302 ctx-f68714cb)
> (logid:79f83157) process hasn't exited
> 2017-08-03 08:39:23,532 WARN [c.c.n.r.VirtualNetworkApplianceManagerImpl]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302 ctx-f68714cb)
> (logid:79f83157) Command: com.cloud.agent.api.Command failed while starting
> virtual router
> 2017-08-03 08:39:23,532 INFO [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302 ctx-f68714cb)
> (logid:79f83157) The guru did not like the answers so stopping
> VM[DomainRouter|r-26-VM]
> 2017-08-03 08:39:23,535 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302 ctx-f68714cb)
> (logid:79f83157) Seq 2-2966746254530314643: Sending { Cmd , MgmtId:
> 7589375051554, via: 2(trl-796-k-cs411-bstoyanov-kvm2), Ver: v1, Flags:
> 100011,
> [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"forceStop":false,"vmName":"r-26-VM","executeInSequence":false,"wait":0}}]
> }
> 2017-08-03 08:39:23,758 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentManager-Handler-14:null) (logid:) Ping from 4(v-1-VM)
> 2017-08-03 08:39:23,790 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentManager-Handler-5:null) (logid:) Ping from 3(s-2-VM)
> 2017-08-03 08:39:27,238 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
> (AsyncJobMgr-Heartbeat-1:ctx-43baf823) (logid:5129ef8e) Begin cleanup expired
> async-jobs
> 2017-08-03 08:39:27,242 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
> (AsyncJobMgr-Heartbeat-1:ctx-43baf823) (logid:5129ef8e) End cleanup expired
> async-jobs
> 2017-08-03 08:39:27,562 INFO [c.c.u.AccountManagerImpl]
> (AccountChecker-1:ctx-72ac9a18) (logid:4f5b1b89) Found 0 removed accounts to
> cleanup
> 2017-08-03 08:39:27,563 INFO [c.c.u.AccountManagerImpl]
> (AccountChecker-1:ctx-72ac9a18) (logid:4f5b1b89) Found 0 disabled accounts to
> cleanup
> 2017-08-03 08:39:27,564 INFO [c.c.u.AccountManagerImpl]
> (AccountChecker-1:ctx-72ac9a18) (logid:4f5b1b89) Found 0 inactive domains to
> cleanup
> 2017-08-03 08:39:27,565 INFO [c.c.u.AccountManagerImpl]
> (AccountChecker-1:ctx-72ac9a18) (logid:4f5b1b89) Found 0 disabled projects to
> cleanup
> 2017-08-03 08:39:27,570 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:ctx-76450825) (logid:bca55810) Found 1 routers to
> update status.
> 2017-08-03 08:39:27,572 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:ctx-76450825) (logid:bca55810) Found 2 VPC networks to
> update Redundant State.
> 2017-08-03 08:39:27,574 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:ctx-76450825) (logid:bca55810) Found 0 networks to
> update RvR status.
> 2017-08-03 08:39:28,098 INFO [o.a.c.e.o.NetworkOrchestrator]
> (Network-Scavenger-1:ctx-8609199c) (logid:5f527cc7) NetworkGarbageCollector
> uses '300' seconds for GC interval.
> 2017-08-03 08:39:28,102 DEBUG [o.a.c.e.o.NetworkOrchestrator]
> (Network-Scavenger-1:ctx-8609199c) (logid:5f527cc7) Network 209 is still free
> but it's not time to shutdown yet: 1501749448
> 2017-08-03 08:39:28,105 DEBUG [c.c.n.NetworkModelImpl]
> (Network-Scavenger-1:ctx-8609199c) (logid:5f527cc7) Network id=212 is not
> ready for GC as it has vms that are Starting at the moment
> 2017-08-03 08:39:28,131 DEBUG [c.c.a.ApiServlet]
> (catalina-exec-3:ctx-64725bb2) (logid:501f80fa) ===START=== 10.1.0.1 -- GET
> signature=GW5N4FsQQmEwb88LLMgUbiAJKVA%3D&apiKey=LIN6rqXuaJwMPfGYFh13qDwYz5VNNz1J2J6qIOWcd3oLQOq0WtD4CwRundBL6rzXToa3lQOC_vKjI3nkHtiD8Q&command=queryAsyncJobResult&response=json&jobid=79f83157-5dbb-4d3e-afd0-90306550030d
> 2017-08-03 08:39:28,150 DEBUG [c.c.a.ApiServlet]
> (catalina-exec-3:ctx-64725bb2 ctx-41a6d119 ctx-7c926123) (logid:501f80fa)
> ===END=== 10.1.0.1 -- GET
> signature=GW5N4FsQQmEwb88LLMgUbiAJKVA%3D&apiKey=LIN6rqXuaJwMPfGYFh13qDwYz5VNNz1J2J6qIOWcd3oLQOq0WtD4CwRundBL6rzXToa3lQOC_vKjI3nkHtiD8Q&command=queryAsyncJobResult&response=json&jobid=79f83157-5dbb-4d3e-afd0-90306550030d
> 2017-08-03 08:39:28,997 DEBUG [c.c.a.t.Request]
> (AgentManager-Handler-17:null) (logid:) Seq 2-2966746254530314643:
> Processing: { Ans: , MgmtId: 7589375051554, via: 2, Ver: v1, Flags: 10,
> [{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
> 2017-08-03 08:39:28,997 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302 ctx-f68714cb)
> (logid:79f83157) Seq 2-2966746254530314643: Received: { Ans: , MgmtId:
> 7589375051554, via: 2(trl-796-k-cs411-bstoyanov-kvm2), Ver: v1, Flags: 10, {
> StopAnswer } }
> 2017-08-03 08:39:28,997 ERROR [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302 ctx-f68714cb)
> (logid:79f83157) Failed to start instance VM[DomainRouter|r-26-VM]
> com.cloud.utils.exception.ExecutionException: Unable to start
> VM:dde05785-343b-425e-b700-40320b71421f due to error in finalizeStart, not
> retrying
> at
> com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1102)
> at
> com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4699)
> at sun.reflect.GeneratedMethodAccessor505.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at
> com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
> at
> com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:4860)
> at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
> at
> org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:558)
> 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
> org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:506)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at java.lang.Thread.run(Thread.java:748)
> 2017-08-03 08:39:29,004 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302 ctx-f68714cb)
> (logid:79f83157) Cleaning up resources for the vm VM[DomainRouter|r-26-VM] in
> Starting state
> 2017-08-03 08:39:29,006 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302 ctx-f68714cb)
> (logid:79f83157) Seq 2-2966746254530314644: Sending { Cmd , MgmtId:
> 7589375051554, via: 2(trl-796-k-cs411-bstoyanov-kvm2), Ver: v1, Flags:
> 100011,
> [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"forceStop":false,"vmName":"r-26-VM","executeInSequence":false,"wait":0}}]
> }
> 2017-08-03 08:39:29,274 DEBUG [c.c.a.t.Request]
> (AgentManager-Handler-18:null) (logid:) Seq 2-2966746254530314644:
> Processing: { Ans: , MgmtId: 7589375051554, via: 2, Ver: v1, Flags: 10,
> [{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
> 2017-08-03 08:39:29,275 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302 ctx-f68714cb)
> (logid:79f83157) Seq 2-2966746254530314644: Received: { Ans: , MgmtId:
> 7589375051554, via: 2(trl-796-k-cs411-bstoyanov-kvm2), Ver: v1, Flags: 10, {
> StopAnswer } }
> 2017-08-03 08:39:29,291 DEBUG [c.c.n.g.ControlNetworkGuru]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302 ctx-f68714cb)
> (logid:79f83157) Released nic: NicProfile[67-26-null-null-null
> 2017-08-03 08:39:29,316 DEBUG [c.c.n.NetworkModelImpl]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302 ctx-f68714cb)
> (logid:79f83157) Service SecurityGroup is not supported in the network id=215
> 2017-08-03 08:39:29,322 DEBUG [o.a.c.e.o.NetworkOrchestrator]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302 ctx-f68714cb)
> (logid:79f83157) Asking VpcVirtualRouter to release
> NicProfile[70-26-0ff9946f-1f91-457d-bd99-09df0d377192-10.0.1.1-null
> 2017-08-03 08:39:29,322 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302 ctx-f68714cb)
> (logid:79f83157) Successfully released network resources for the vm
> VM[DomainRouter|r-26-VM]
> 2017-08-03 08:39:29,322 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302 ctx-f68714cb)
> (logid:79f83157) Successfully cleanued up resources for the vm
> VM[DomainRouter|r-26-VM] in Starting state
> 2017-08-03 08:39:29,332 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302 ctx-f68714cb)
> (logid:79f83157) VM state transitted from :Starting to Stopped with event:
> OperationFailedvm's original host id: null new host id: null host id before
> state transition: 2
> 2017-08-03 08:39:29,337 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302 ctx-f68714cb)
> (logid:79f83157) Hosts's actual total CPU: 4797 and CPU after applying
> overprovisioning: 9594
> 2017-08-03 08:39:29,337 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302 ctx-f68714cb)
> (logid:79f83157) Hosts's actual total RAM: 7515656192 and RAM after applying
> overprovisioning: 7515656192
> 2017-08-03 08:39:29,337 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302 ctx-f68714cb)
> (logid:79f83157) release cpu from host: 2, old used: 1600,reserved: 0, actual
> total: 4797, total with overprovisioning: 9594; new used: 1100,reserved:0;
> movedfromreserved: false,moveToReserveredfalse
> 2017-08-03 08:39:29,337 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302 ctx-f68714cb)
> (logid:79f83157) release mem from host: 2, old used: 2013265920,reserved: 0,
> total: 7515656192; new used: 1744830464,reserved:0; movedfromreserved:
> false,moveToReserveredfalse
> 2017-08-03 08:39:29,341 ERROR [c.c.v.VmWorkJobHandlerProxy]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302 ctx-f68714cb)
> (logid:79f83157) Invocation exception, caused by:
> com.cloud.exception.AgentUnavailableException: Resource [Host:2] is
> unreachable: Host 2: Unable to start instance due to Unable to start
> VM:dde05785-343b-425e-b700-40320b71421f due to error in finalizeStart, not
> retrying
> 2017-08-03 08:39:29,342 INFO [c.c.v.VmWorkJobHandlerProxy]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302 ctx-f68714cb)
> (logid:79f83157) Rethrow exception
> com.cloud.exception.AgentUnavailableException: Resource [Host:2] is
> unreachable: Host 2: Unable to start instance due to Unable to start
> VM:dde05785-343b-425e-b700-40320b71421f due to error in finalizeStart, not
> retrying
> 2017-08-03 08:39:29,342 DEBUG [c.c.v.VmWorkJobDispatcher]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302) (logid:79f83157) Done
> with run of VM work job: com.cloud.vm.VmWorkStart for VM 26, job origin: 300
> 2017-08-03 08:39:29,342 ERROR [c.c.v.VmWorkJobDispatcher]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302) (logid:79f83157) Unable
> to complete AsyncJobVO {id:302, userId: 2, accountId: 2, instanceType: null,
> instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
> rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAGnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AA5SZXN0YXJ0TmV0d29ya3QAP3JPMEFCWE55QUJGcVlYWmhMbXhoYm1jdVFtOXZiR1ZoYnMwZ2NvRFZuUHJ1QWdBQldnQUZkbUZzZFdWNGNBRXhw,
> cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
> null, initMsid: 7589375051554, completeMsid: null, lastUpdated: null,
> lastPolled: null, created: Thu Aug 03 08:38:29 UTC 2017}, job origin:300
> com.cloud.exception.AgentUnavailableException: Resource [Host:2] is
> unreachable: Host 2: Unable to start instance due to Unable to start
> VM:dde05785-343b-425e-b700-40320b71421f due to error in finalizeStart, not
> retrying
> at
> com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1138)
> at
> com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4699)
> at sun.reflect.GeneratedMethodAccessor505.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at
> com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
> at
> com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:4860)
> at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
> at
> org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:558)
> 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
> org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:506)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at java.lang.Thread.run(Thread.java:748)
> Caused by: com.cloud.utils.exception.ExecutionException: Unable to start
> VM:dde05785-343b-425e-b700-40320b71421f due to error in finalizeStart, not
> retrying
> at
> com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1102)
> at
> com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4699)
> at sun.reflect.GeneratedMethodAccessor505.invoke(Unknown Source)
> ... 17 more
> 2017-08-03 08:39:29,343 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302) (logid:79f83157) Complete
> async job-302, jobStatus: FAILED, resultCode: 0, result:
> rO0ABXNyAC1jb20uY2xvdWQuZXhjZXB0aW9uLkFnZW50VW5hdmFpbGFibGVFeGNlcHRpb24AAAAAVk1PdwIAAHhyADBjb20uY2xvdWQuZXhjZXB0aW9uLlJlc291cmNlVW5hdmFpbGFibGVFeGNlcHRpb24AAAAAVk1PfwIAAkoAA19pZEwABl9zY29wZXQAEUxqYXZhL2xhbmcvQ2xhc3M7eHIAImNvbS5jbG91ZC5leGNlcHRpb24uQ2xvdWRFeGNlcHRpb2556I4b8eRExwIAAkwAC2NzRXJyb3JDb2RldAATTGphdmEvbGFuZy9JbnRlZ2VyO0wABmlkTGlzdHQAFUxqYXZhL3V0aWwvQXJyYXlMaXN0O3hyABNqYXZhLmxhbmcuRXhjZXB0aW9u0P0fPho7HMQCAAB4cgATamF2YS5sYW5nLlRocm93YWJsZdXGNSc5d7jLAwAETAAFY2F1c2V0ABVMamF2YS9sYW5nL1Rocm93YWJsZTtMAA1kZXRhaWxNZXNzYWdldAASTGphdmEvbGFuZy9TdHJpbmc7WwAKc3RhY2tUcmFjZXQAHltMamF2YS9sYW5nL1N0YWNrVHJhY2VFbGVtZW50O0wAFHN1cHByZXNzZWRFeGNlcHRpb25zdAAQTGphdmEvdXRpbC9MaXN0O3hwc3IALGNvbS5jbG91ZC51dGlscy5leGNlcHRpb24uRXhlY3V0aW9uRXhjZXB0aW9uAAAAAFZNT34CAAFJAAtjc0Vycm9yQ29kZXhxAH4ABnEAfgAOdABkVW5hYmxlIHRvIHN0YXJ0ICBWTTpkZGUwNTc4NS0zNDNiLTQyNWUtYjcwMC00MDMyMGI3MTQyMWYgZHVlIHRvIGVycm9yIGluIGZpbmFsaXplU3RhcnQsIG5vdCByZXRyeWluZ3VyAB5bTGphdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudDsCRio8PP0iOQIAAHhwAAAAFHNyABtqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnRhCcWaJjbdhQIABEkACmxpbmVOdW1iZXJMAA5kZWNsYXJpbmdDbGFzc3EAfgAJTAAIZmlsZU5hbWVxAH4ACUwACm1ldGhvZE5hbWVxAH4ACXhwAAAETnQAJmNvbS5jbG91ZC52bS5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsdAAeVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbC5qYXZhdAAQb3JjaGVzdHJhdGVTdGFydHNxAH4AEgAAEltxAH4AFHEAfgAVcQB-ABZzcQB-ABL_____dAAmc3VuLnJlZmxlY3QuR2VuZXJhdGVkTWV0aG9kQWNjZXNzb3I1MDVwdAAGaW52b2tlc3EAfgASAAAAK3QAKHN1bi5yZWZsZWN0LkRlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGx0ACFEZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsLmphdmFxAH4AGnNxAH4AEgAAAfJ0ABhqYXZhLmxhbmcucmVmbGVjdC5NZXRob2R0AAtNZXRob2QuamF2YXEAfgAac3EAfgASAAAAa3QAImNvbS5jbG91ZC52bS5WbVdvcmtKb2JIYW5kbGVyUHJveHl0ABpWbVdvcmtKb2JIYW5kbGVyUHJveHkuamF2YXQAD2hhbmRsZVZtV29ya0pvYnNxAH4AEgAAEvxxAH4AFHEAfgAVcQB-ACRzcQB-ABIAAABmdAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JzcQB-ABIAAAIudAA_b3JnLmFwYWNoZS5jbG91ZHN0YWNrLmZyYW1ld29yay5qb2JzLmltcGwuQXN5bmNKb2JNYW5hZ2VySW1wbCQ1dAAYQXN5bmNKb2JNYW5hZ2VySW1wbC5qYXZhdAAMcnVuSW5Db250ZXh0c3EAfgASAAAAMXQAPm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZSQxdAAbTWFuYWdlZENvbnRleHRSdW5uYWJsZS5qYXZhdAADcnVuc3EAfgASAAAAOHQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHNxAH4AEgAAAGd0AEBvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0cQB-ADR0AA9jYWxsV2l0aENvbnRleHRzcQB-ABIAAAA1cQB-ADdxAH4ANHQADnJ1bldpdGhDb250ZXh0c3EAfgASAAAALnQAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgAwcQB-ADFzcQB-ABIAAAH6cQB-ACtxAH4ALHEAfgAxc3EAfgASAAAB_3QALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgA1c3EAfgASAAABCnQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFxAH4AMXNxAH4AEgAABH10ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnNxAH4AEgAAAnB0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-AEZxAH4AMXNxAH4AEgAAAux0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4AMXNyACZqYXZhLnV0aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlTGlzdPwPJTG17I4QAgABTAAEbGlzdHEAfgALeHIALGphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVDb2xsZWN0aW9uGUIAgMte9x4CAAFMAAFjdAAWTGphdmEvdXRpbC9Db2xsZWN0aW9uO3hwc3IAE2phdmEudXRpbC5BcnJheUxpc3R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4cQB-AFJ4AAAAAHQArlJlc291cmNlIFtIb3N0OjJdIGlzIHVucmVhY2hhYmxlOiBIb3N0IDI6IFVuYWJsZSB0byBzdGFydCBpbnN0YW5jZSBkdWUgdG8gVW5hYmxlIHRvIHN0YXJ0ICBWTTpkZGUwNTc4NS0zNDNiLTQyNWUtYjcwMC00MDMyMGI3MTQyMWYgZHVlIHRvIGVycm9yIGluIGZpbmFsaXplU3RhcnQsIG5vdCByZXRyeWluZ3VxAH4AEAAAABRzcQB-ABIAAARycQB-ABRxAH4AFXEAfgAWc3EAfgASAAASW3EAfgAUcQB-ABVxAH4AFnNxAH4AEv____9xAH4AGXBxAH4AGnNxAH4AEgAAACtxAH4AHHEAfgAdcQB-ABpzcQB-ABIAAAHycQB-AB9xAH4AIHEAfgAac3EAfgASAAAAa3EAfgAicQB-ACNxAH4AJHNxAH4AEgAAEvxxAH4AFHEAfgAVcQB-ACRzcQB-ABIAAABmcQB-ACdxAH4AKHEAfgApc3EAfgASAAACLnEAfgArcQB-ACxxAH4ALXNxAH4AEgAAADFxAH4AL3EAfgAwcQB-ADFzcQB-ABIAAAA4cQB-ADNxAH4ANHEAfgA1c3EAfgASAAAAZ3EAfgA3cQB-ADRxAH4AOHNxAH4AEgAAADVxAH4AN3EAfgA0cQB-ADpzcQB-ABIAAAAucQB-ADxxAH4AMHEAfgAxc3EAfgASAAAB-nEAfgArcQB-ACxxAH4AMXNxAH4AEgAAAf9xAH4AP3EAfgBAcQB-ADVzcQB-ABIAAAEKcQB-AEJxAH4AQ3EAfgAxc3EAfgASAAAEfXEAfgBFcQB-AEZxAH4AR3NxAH4AEgAAAnBxAH4ASXEAfgBGcQB-ADFzcQB-ABIAAALscQB-AEtxAH4ATHEAfgAxcQB-AFB4c3IAEWphdmEubGFuZy5JbnRlZ2VyEuKgpPeBhzgCAAFJAAV2YWx1ZXhyABBqYXZhLmxhbmcuTnVtYmVyhqyVHQuU4IsCAAB4cAAAEL1zcQB-AFEAAAAAdwQAAAAAeAAAAAAAAAACdnIAE2NvbS5jbG91ZC5ob3N0Lkhvc3QCeM6f4EWIyQIAAHhw
> 2017-08-03 08:39:29,344 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302) (logid:79f83157) Publish
> async job-302 complete on message bus
> 2017-08-03 08:39:29,344 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302) (logid:79f83157) Wake up
> jobs related to job-302
> 2017-08-03 08:39:29,344 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302) (logid:79f83157) Update
> db status for job-302
> 2017-08-03 08:39:29,345 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302) (logid:79f83157) Wake up
> jobs joined with job-302 and disjoin all subjobs created from job- 302
> 2017-08-03 08:39:29,353 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302) (logid:79f83157) Done
> executing com.cloud.vm.VmWorkStart for job-302
> 2017-08-03 08:39:29,355 INFO [o.a.c.f.j.i.AsyncJobMonitor]
> (Work-Job-Executor-76:ctx-51dcb30c job-300/job-302) (logid:79f83157) Remove
> job-302 from job monitoring
> 2017-08-03 08:39:29,362 WARN [c.c.n.v.VpcManagerImpl]
> (API-Job-Executor-85:ctx-9f88d1bf job-300 ctx-06eda8fe) (logid:79f83157)
> Failed to start vpc [VPC [8-TestVPC-4Y676O] due to
> com.cloud.exception.AgentUnavailableException: Resource [Host:2] is
> unreachable: Host 2: Unable to start instance due to Unable to start
> VM:dde05785-343b-425e-b700-40320b71421f due to error in finalizeStart, not
> retrying
> at
> com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1138)
> at
> com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4699)
> at sun.reflect.GeneratedMethodAccessor505.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at
> com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
> at
> com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:4860)
> at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
> at
> org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:558)
> 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
> org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:506)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at java.lang.Thread.run(Thread.java:748)
> Caused by: com.cloud.utils.exception.ExecutionException: Unable to start
> VM:dde05785-343b-425e-b700-40320b71421f due to error in finalizeStart, not
> retrying
> at
> com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1102)
> at
> com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4699)
> at sun.reflect.GeneratedMethodAccessor505.invoke(Unknown Source)
> ... 17 more
> 2017-08-03 08:39:29,362 WARN [c.c.n.v.VpcManagerImpl]
> (API-Job-Executor-85:ctx-9f88d1bf job-300 ctx-06eda8fe) (logid:79f83157)
> Failed to start vpc as a part of VPC [VPC [8-TestVPC-4Y676O] restart process
> 2017-08-03 08:39:29,362 DEBUG [c.c.n.v.VpcManagerImpl]
> (API-Job-Executor-85:ctx-9f88d1bf job-300 ctx-06eda8fe) (logid:79f83157)
> Updating VPC [VPC [8-TestVPC-4Y676O] with restartRequired=true
> 2017-08-03 08:39:29,378 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-85:ctx-9f88d1bf job-300) (logid:79f83157) Complete async
> job-300, jobStatus: FAILED, resultCode: 530, result:
> org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Failed
> to restart VPC"}
> 2017-08-03 08:39:29,379 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-85:ctx-9f88d1bf job-300) (logid:79f83157) Publish async
> job-300 complete on message bus
> 2017-08-03 08:39:29,379 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-85:ctx-9f88d1bf job-300) (logid:79f83157) Wake up jobs
> related to job-300
> 2017-08-03 08:39:29,379 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-85:ctx-9f88d1bf job-300) (logid:79f83157) Update db status
> for job-300
> 2017-08-03 08:39:29,380 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-85:ctx-9f88d1bf job-300) (logid:79f83157) Wake up jobs
> joined with job-300 and disjoin all subjobs created from job- 300
> 2017-08-03 08:39:29,384 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-85:ctx-9f88d1bf job-300) (logid:79f83157) Done executing
> org.apache.cloudstack.api.command.user.vpc.RestartVPCCmd for job-300
> 2017-08-03 08:39:29,384 INFO [o.a.c.f.j.i.AsyncJobMonitor]
> (API-Job-Executor-85:ctx-9f88d1bf job-300) (logid:79f83157) Remove job-300
> from job monitoring
> 2017-08-03 08:39:29,605 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentManager-Handler-3:null) (logid:) SeqA 4-1030: Processing Seq 4-1030: {
> Cmd , MgmtId: -1, via: 4, Ver: v1, Flags: 11,
> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n
> \"connections\": []\n}","wait":0}}] }
> 2017-08-03 08:39:29,609 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentManager-Handler-3:null) (logid:) SeqA 4-1030: Sending Seq 4-1030: {
> Ans: , MgmtId: 7589375051554, via: 4, Ver: v1, Flags: 100010,
> [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2017-08-03 08:39:30,788 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentManager-Handler-16:null) (logid:) Ping from
> 1(trl-796-k-cs411-bstoyanov-kvm1)
> 2017-08-03 08:39:30,788 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-16:null) (logid:) Process host VM state report from
> ping process. host: 1
> 2017-08-03 08:39:30,792 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-16:null) (logid:) Process VM state report. host: 1,
> number of records in report: 2
> 2017-08-03 08:39:30,792 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-16:null) (logid:) VM state report. host: 1, vm id: 23,
> power state: PowerOn
> 2017-08-03 08:39:30,794 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-16:null) (logid:) VM power state does not change, skip
> DB writing. vm id: 23
> 2017-08-03 08:39:30,794 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-16:null) (logid:) VM state report. host: 1, vm id: 24,
> power state: PowerOn
> 2017-08-03 08:39:30,796 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-16:null) (logid:) VM power state does not change, skip
> DB writing. vm id: 24
> 2017-08-03 08:39:30,799 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-16:null) (logid:) Done with process of VM state report.
> host: 1
> 2017-08-03 08:39:31,454 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentManager-Handler-1:null) (logid:) Ping from
> 2(trl-796-k-cs411-bstoyanov-kvm2)
> 2017-08-03 08:39:31,454 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-1:null) (logid:) Process host VM state report from ping
> process. host: 2
> 2017-08-03 08:39:31,459 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-1:null) (logid:) Process VM state report. host: 2,
> number of records in report: 3
> 2017-08-03 08:39:31,459 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-1:null) (logid:) VM state report. host: 2, vm id: 1,
> power state: PowerOn
> 2017-08-03 08:39:31,461 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-1:null) (logid:) VM power state does not change, skip
> DB writing. vm id: 1
> 2017-08-03 08:39:31,461 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-1:null) (logid:) VM state report. host: 2, vm id: 2,
> power state: PowerOn
> 2017-08-03 08:39:31,462 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-1:null) (logid:) VM power state does not change, skip
> DB writing. vm id: 2
> 2017-08-03 08:39:31,463 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-1:null) (logid:) VM state report. host: 2, vm id: 25,
> power state: PowerOn
> 2017-08-03 08:39:31,464 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-1:null) (logid:) VM power state does not change, skip
> DB writing. vm id: 25
> 2017-08-03 08:39:31,467 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-1:null) (logid:) Done with process of VM state report.
> host: 2
> 2017-08-03 08:39:33,276 DEBUG [c.c.a.ApiServlet]
> (catalina-exec-6:ctx-1adcf071) (logid:8ff7ae7a) ===START=== 10.1.0.1 -- GET
> signature=GW5N4FsQQmEwb88LLMgUbiAJKVA%3D&apiKey=LIN6rqXuaJwMPfGYFh13qDwYz5VNNz1J2J6qIOWcd3oLQOq0WtD4CwRundBL6rzXToa3lQOC_vKjI3nkHtiD8Q&command=queryAsyncJobResult&response=json&jobid=79f83157-5dbb-4d3e-afd0-90306550030d
> 2017-08-03 08:39:33,292 DEBUG [c.c.a.ApiServlet]
> (catalina-exec-6:ctx-1adcf071 ctx-2642af92 ctx-dd852788) (logid:8ff7ae7a)
> ===END=== 10.1.0.1 -- GET
> signature=GW5N4FsQQmEwb88LLMgUbiAJKVA%3D&apiKey=LIN6rqXuaJwMPfGYFh13qDwYz5VNNz1J2J6qIOWcd3oLQOq0WtD4CwRundBL6rzXToa3lQOC_vKjI3nkHtiD8Q&command=queryAsyncJobResult&response=json&jobid=79f83157-5dbb-4d3e-afd0-90306550030d{code}
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
