cloudstack-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Boris Stoyanov (JIRA)" <j...@apache.org>
Subject [jira] [Created] (CLOUDSTACK-10028) Rebooting router fails
Date Thu, 03 Aug 2017 08:48:01 GMT
Boris Stoyanov created CLOUDSTACK-10028:
-------------------------------------------

             Summary: 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


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)


Mime
View raw message