Uploaded image for project: 'CloudStack'
  1. CloudStack
  2. CLOUDSTACK-9370

Failed to create VPC: Unable to start VPC VR (VM DomainRouter) due to error in finalizeStart, not retrying

Attach filesAttach ScreenshotAdd voteVotersWatch issueWatchersCreate sub-taskLinkCloneUpdate Comment AuthorReplace String in CommentUpdate Comment VisibilityDelete Comments
    XMLWordPrintableJSON

Details

    • Bug
    • Status: Open
    • Critical
    • Resolution: Unresolved
    • 4.9.0
    • 4.9.1.0
    • Virtual Router
    • Security Level: Public (Anyone can view this level - this is the default.)
    • None
    • Centos El7
      KVM
      OpenvSwitch (VLAN 0)
      NFS (primary/secondary)

    Description

      I am unable to create VPCs on latest cloudstack master due to the following error:

      Root Cause Error in Agent log
      2016-04-27 02:31:03,134 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) [INFO] update_config.py :: Processing incoming file => ip_associations.json[INFO] Processing JSON file ip_associations.jsonTraceback (most recent call last):  File "/opt/cloud/bin/update_config.py", line 140, in <module>    process_file()  File "/opt/cloud/bin/update_config.py", line 52, in process_file    qf.load(None)  File "/opt/cloud/bin/merge.py", line 258, in load    proc = updateDataBag(self)  File "/opt/cloud/bin/merge.py", line 91, in __init__    self.process()  File "/opt/cloud/bin/merge.py", line 103, in process    dbag = self.processIP(self.db.getDataBag())  File "/opt/cloud/bin/merge.py", line 190, in processIP    dbag = cs_ip.merge(dbag, ip)  File "/opt/cloud/bin/cs_ip.py", line 32, in merge    ip['device'] = 'eth' + str(ip['nic_dev_id'])KeyError: 'nic_dev_id'
      2016-04-27 02:31:03,135 DEBUG [resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) Processing ScriptConfigItem, executing update_config.py ip_associations.json took 911ms
      
      Root Cause Error in Management Server log
      2016-04-27 02:30:19,975 DEBUG [c.c.a.m.ClusteredAgentAttache] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Seq 9-332421947495286159: Forwarding Seq 9-332421947495286159:  { Cmd , MgmtId: 275619427298304, via: 9(ovs-2.mvdcvtb16.us.alcatel-lucent.com), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StartCommand":{"vm":{"id":252,"name":"r-252-VM","type":"DomainRouter","cpus":1,"minSpeed":500,"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.1.1.1/16 domain=cs2cloud.internal dns1=128.251.10.29 template=domP name=r-252-VM eth0ip=169.254.1.123 eth0mask=255.255.0.0 type=vpcrouter disable_rp_filter=true baremetalnotificationsecuritykey=0oLpL4swbL6Yu_xsuRdyjwmmyPHAU1V-iMpmMNKO00vNIP5bxronvhQZ_qehiEZ99Eo9avCHg9uLh1cbiz7pQA baremetalnotificationapikey=wEax_CyEaKZHn8ZkPBQLQaibjSWZ0OYJuEQA3l2RUA41GXZxaie9P6oQPeNlzjIGl-fDpKWp9MkAEQOJYvE4vA host=10.31.59.151 port=8080","enableHA":true,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"0Q5cib8VX0wIh1nvNsJktw","params":{},"uuid":"2e54aa49-ae38-405d-b1fe-f14b30053ab6","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"767e7794-1c87-4957-834a-a92eb711a15d","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"bf0515dd-fead-3151-b1a0-9d88c468583a","id":1,"poolType":"NetworkFilesystem","host":"mvdcvtb16.us.alcatel-lucent.com","path":"/mvdcvtb16/storage","port":2049,"url":"NetworkFilesystem://mvdcvtb16.us.alcatel-lucent.com/mvdcvtb16/storage/?ROLE=Primary&STOREUUID=bf0515dd-fead-3151-b1a0-9d88c468583a"}},"name":"ROOT-252","size":322954240,"path":"767e7794-1c87-4957-834a-a92eb711a15d","volumeId":252,"vmName":"r-252-VM","accountId":2,"format":"QCOW2","provisioningType":"THIN","id":252,"deviceId":0,"hypervisorType":"KVM"}},"diskSeq":0,"path":"767e7794-1c87-4957-834a-a92eb711a15d","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"mvdcvtb16.us.alcatel-lucent.com","volumeSize":"322954240"}}],"nics":[{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"pxeDisable":true,"nicUuid":"bf300ca0-afdb-4277-ac71-b7d0d041e29a","uuid":"1ec6ef5d-bed2-475a-9abb-122750fa8ea5","ip":"169.254.1.123","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:01:7b","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false}]},"hostIp":"10.100.100.12","executeInSequence":false,"wait":0}},{"com.cloud.agent.api.check.CheckSshCommand":{"ip":"169.254.1.123","port":3922,"interval":6,"retries":100,"name":"r-252-VM","wait":0}},{"com.cloud.agent.api.GetDomRVersionCmd":{"accessDetails":{"router.name":"r-252-VM","router.ip":"169.254.1.123"},"wait":0}},{"com.cloud.agent.api.PlugNicCommand":{"nic":{"deviceId":1,"networkRateMbps":200,"defaultNic":true,"pxeDisable":true,"nicUuid":"8a8486f8-9655-499b-9a78-bc76849254d3","uuid":"cdfc99be-4436-4740-afea-b99de3a436b4","ip":"10.31.59.187","netmask":"255.255.224.0","gateway":"10.31.32.1","mac":"06:6e:e8:00:00:41","broadcastType":"Vlan","type":"Public","broadcastUri":"vlan://0","isolationUri":"vlan://0","isSecurityGroupEnabled":false,"name":"cloudbr0"},"instanceName":"r-252-VM","vmType":"DomainRouter","wait":0}},{"com.cloud.agent.api.routing.IpAssocVpcCommand":{"ipAddresses":[{"accountId":2,"publicIp":"10.31.59.187","sourceNat":true,"add":true,"oneToOneNat":false,"firstIP":false,"broadcastUri":"vlan://0","vlanGateway":"10.31.32.1","vlanNetmask":"255.255.224.0","vifMacAddress":"06:6e:e8:00:00:41","networkRate":200,"trafficType":"Public","networkName":"cloudbr0","newNic":false}],"accessDetails":{"zone.network.type":"Advanced","router.name":"r-252-VM","router.ip":"169.254.1.123","router.guest.ip":"10.31.59.187"},"wait":0}},{"com.cloud.agent.api.routing.SetSourceNatCommand":{"ipAddress":{"accountId":2,"publicIp":"10.31.59.187","sourceNat":true,"add":true,"oneToOneNat":false,"firstIP":false,"broadcastUri":"vlan://0","vlanGateway":"10.31.32.1","vlanNetmask":"255.255.224.0","vifMacAddress":"06:6e:e8:00:00:41","networkRate":200,"trafficType":"Public","networkName":"cloudbr0","newNic":false},"add":true,"accessDetails":{"zone.network.type":"Advanced","router.ip":"169.254.1.123","router.name":"r-252-VM"},"wait":0}},{}] } to 275619427298560
      2016-04-27 02:31:03,141 DEBUG [c.c.a.t.Request] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Seq 9-332421947495286159: Received:  { Ans: , MgmtId: 275619427298304, via: 9(ovs-2.mvdcvtb16.us.alcatel-lucent.com), Ver: v1, Flags: 110, { StartAnswer, CheckSshAnswer, GetDomRVersionAnswer, PlugNicAnswer, GroupAnswer, Answer, Answer } }
      2016-04-27 02:31:03,152 WARN  [o.a.c.alerts] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa)  alertType:: 9 // dataCenterId:: 1 // podId:: 1 // clusterId:: null // message:: Command: com.cloud.agent.api.routing.GroupCommand failed while starting virtual router
      2016-04-27 02:31:03,160 ERROR [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) null
      2016-04-27 02:31:03,160 WARN  [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Command: com.cloud.agent.api.routing.GroupCommand failed while starting virtual router
      2016-04-27 02:31:03,160 INFO  [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) The guru did not like the answers so stopping VM[DomainRouter|r-252-VM]
      2016-04-27 02:31:03,165 DEBUG [c.c.a.m.ClusteredAgentAttache] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Seq 9-332421947495286162: Forwarding Seq 9-332421947495286162:  { Cmd , MgmtId: 275619427298304, via: 9(ovs-2.mvdcvtb16.us.alcatel-lucent.com), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"r-252-VM","wait":0}}] } to 275619427298560
      2016-04-27 02:31:09,387 DEBUG [c.c.a.t.Request] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Seq 9-332421947495286162: Received:  { Ans: , MgmtId: 275619427298304, via: 9(ovs-2.mvdcvtb16.us.alcatel-lucent.com), Ver: v1, Flags: 10, { StopAnswer } }
      2016-04-27 02:31:09,387 ERROR [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Failed to start instance VM[DomainRouter|r-252-VM]
      2016-04-27 02:31:09,396 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Cleaning up resources for the vm VM[DomainRouter|r-252-VM] in Starting state
      2016-04-27 02:31:09,402 DEBUG [c.c.a.m.ClusteredAgentAttache] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Seq 9-332421947495286163: Forwarding Seq 9-332421947495286163:  { Cmd , MgmtId: 275619427298304, via: 9(ovs-2.mvdcvtb16.us.alcatel-lucent.com), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"r-252-VM","wait":0}}] } to 275619427298560
      2016-04-27 02:31:09,652 DEBUG [c.c.a.t.Request] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Seq 9-332421947495286163: Received:  { Ans: , MgmtId: 275619427298304, via: 9(ovs-2.mvdcvtb16.us.alcatel-lucent.com), Ver: v1, Flags: 10, { StopAnswer } }
      2016-04-27 02:31:09,669 DEBUG [c.c.n.g.ControlNetworkGuru] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Released nic: NicProfile[715-252-null-null-null
      2016-04-27 02:31:09,686 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Successfully released network resources for the vm VM[DomainRouter|r-252-VM]
      2016-04-27 02:31:09,686 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Successfully cleanued up resources for the vm VM[DomainRouter|r-252-VM] in Starting state
      2016-04-27 02:31:09,704 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 9
      2016-04-27 02:31:09,709 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Hosts's actual total CPU: 23100 and CPU after applying overprovisioning: 23100
      2016-04-27 02:31:09,709 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Hosts's actual total RAM: 22296875008 and RAM after applying overprovisioning: 22296875008
      2016-04-27 02:31:09,709 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) release cpu from host: 9, old used: 1500,reserved: 0, actual total: 23100, total with overprovisioning: 23100; new used: 1000,reserved:0; movedfromreserved: false,moveToReserveredfalse
      2016-04-27 02:31:09,709 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) release mem from host: 9, old used: 1342177280,reserved: 0, total: 22296875008; new used: 1073741824,reserved:0; movedfromreserved: false,moveToReserveredfalse
      2016-04-27 02:31:09,716 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Invocation exception, caused by: com.cloud.exception.AgentUnavailableException: Resource [Host:9] is unreachable: Host 9: Unable to start instance due to Unable to start  VM:2e54aa49-ae38-405d-b1fe-f14b30053ab6 due to error in finalizeStart, not retrying
      2016-04-27 02:31:09,716 INFO  [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Rethrow exception com.cloud.exception.AgentUnavailableException: Resource [Host:9] is unreachable: Host 9: Unable to start instance due to Unable to start  VM:2e54aa49-ae38-405d-b1fe-f14b30053ab6 due to error in finalizeStart, not retrying
      2016-04-27 02:31:09,716 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160) (logid:6b2d4faa) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 252, job origin: 1159
      2016-04-27 02:31:09,716 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160) (logid:6b2d4faa) Unable to complete AsyncJobVO {id:1160, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAA_HQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AA5SZXN0YXJ0TmV0d29ya3QAP3JPMEFCWE55QUJGcVlYWmhMbXhoYm1jdVFtOXZiR1ZoYnMwZ2NvRFZuUHJ1QWdBQldnQUZkbUZzZFdWNGNBRXhw, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 275619427298304, completeMsid: null, lastUpdated: null, lastPolled: null, created: Wed Apr 27 02:30:18 PDT 2016}, job origin:1159
      2016-04-27 02:31:09,734 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160) (logid:6b2d4faa) Complete async job-1160, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyAC1jb20uY2xvdWQuZXhjZXB0aW9uLkFnZW50VW5hdmFpbGFibGVFeGNlcHRpb24AAAAAVk1PdwIAAHhyADBjb20uY2xvdWQuZXhjZXB0aW9uLlJlc291cmNlVW5hdmFpbGFibGVFeGNlcHRpb24AAAAAVk1PfwIAAkoAA19pZEwABl9zY29wZXQAEUxqYXZhL2xhbmcvQ2xhc3M7eHIAImNvbS5jbG91ZC5leGNlcHRpb24uQ2xvdWRFeGNlcHRpb2556I4b8eRExwIAAkwAC2NzRXJyb3JDb2RldAATTGphdmEvbGFuZy9JbnRlZ2VyO0wABmlkTGlzdHQAFUxqYXZhL3V0aWwvQXJyYXlMaXN0O3hyABNqYXZhLmxhbmcuRXhjZXB0aW9u0P0fPho7HMQCAAB4cgATamF2YS5sYW5nLlRocm93YWJsZdXGNSc5d7jLAwAETAAFY2F1c2V0ABVMamF2YS9sYW5nL1Rocm93YWJsZTtMAA1kZXRhaWxNZXNzYWdldAASTGphdmEvbGFuZy9TdHJpbmc7WwAKc3RhY2tUcmFjZXQAHltMamF2YS9sYW5nL1N0YWNrVHJhY2VFbGVtZW50O0wAFHN1cHByZXNzZWRFeGNlcHRpb25zdAAQTGphdmEvdXRpbC9MaXN0O3hwc3IALGNvbS5jbG91ZC51dGlscy5leGNlcHRpb24uRXhlY3V0aW9uRXhjZXB0aW9uAAAAAFZNT34CAAFJAAtjc0Vycm9yQ29kZXhxAH4ABnEAfgAOdABkVW5hYmxlIHRvIHN0YXJ0ICBWTToyZTU0YWE0OS1hZTM4LTQwNWQtYjFmZS1mMTRiMzAwNTNhYjYgZHVlIHRvIGVycm9yIGluIGZpbmFsaXplU3RhcnQsIG5vdCByZXRyeWluZ3VyAB5bTGphdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudDsCRio8PP0iOQIAAHhwAAAAFXNyABtqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnRhCcWaJjbdhQIABEkACmxpbmVOdW1iZXJMAA5kZWNsYXJpbmdDbGFzc3EAfgAJTAAIZmlsZU5hbWVxAH4ACUwACm1ldGhvZE5hbWVxAH4ACXhwAAAEPHQAJmNvbS5jbG91ZC52bS5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsdAAeVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbC5qYXZhdAAQb3JjaGVzdHJhdGVTdGFydHNxAH4AEgAAEeRxAH4AFHEAfgAVcQB-ABZzcQB-ABL____-dAAkc3VuLnJlZmxlY3QuTmF0aXZlTWV0aG9kQWNjZXNzb3JJbXBsdAAdTmF0aXZlTWV0aG9kQWNjZXNzb3JJbXBsLmphdmF0AAdpbnZva2Uwc3EAfgASAAAAOXEAfgAZcQB-ABp0AAZpbnZva2VzcQB-ABIAAAArdAAoc3VuLnJlZmxlY3QuRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbHQAIURlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGwuamF2YXEAfgAdc3EAfgASAAACXnQAGGphdmEubGFuZy5yZWZsZWN0Lk1ldGhvZHQAC01ldGhvZC5qYXZhcQB-AB1zcQB-ABIAAABrdAAiY29tLmNsb3VkLnZtLlZtV29ya0pvYkhhbmRsZXJQcm94eXQAGlZtV29ya0pvYkhhbmRsZXJQcm94eS5qYXZhdAAPaGFuZGxlVm1Xb3JrSm9ic3EAfgASAAAShXEAfgAUcQB-ABVxAH4AJ3NxAH4AEgAAAGZ0ACBjb20uY2xvdWQudm0uVm1Xb3JrSm9iRGlzcGF0Y2hlcnQAGFZtV29ya0pvYkRpc3BhdGNoZXIuamF2YXQABnJ1bkpvYnNxAH4AEgAAAip0AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRzcQB-ABIAAAAxdAA-b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlJDF0ABtNYW5hZ2VkQ29udGV4dFJ1bm5hYmxlLmphdmF0AANydW5zcQB-ABIAAAA4dABCb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dCQxdAAaRGVmYXVsdE1hbmFnZWRDb250ZXh0LmphdmF0AARjYWxsc3EAfgASAAAAZ3QAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4AN3QAD2NhbGxXaXRoQ29udGV4dHNxAH4AEgAAADVxAH4AOnEAfgA3dAAOcnVuV2l0aENvbnRleHRzcQB-ABIAAAAudAA8b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlcQB-ADNxAH4ANHNxAH4AEgAAAfZxAH4ALnEAfgAvcQB-ADRzcQB-ABIAAAHXdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuRXhlY3V0b3JzJFJ1bm5hYmxlQWRhcHRlcnQADkV4ZWN1dG9ycy5qYXZhcQB-ADhzcQB-ABIAAAEGdAAfamF2YS51dGlsLmNvbmN1cnJlbnQuRnV0dXJlVGFza3QAD0Z1dHVyZVRhc2suamF2YXEAfgA0c3EAfgASAAAEeXQAJ2phdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvcnQAF1RocmVhZFBvb2xFeGVjdXRvci5qYXZhdAAJcnVuV29ya2Vyc3EAfgASAAACZ3QALmphdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvciRXb3JrZXJxAH4ASXEAfgA0c3EAfgASAAAC6XQAEGphdmEubGFuZy5UaHJlYWR0AAtUaHJlYWQuamF2YXEAfgA0c3IAJmphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVMaXN0_A8lMbXsjhACAAFMAARsaXN0cQB-AAt4cgAsamF2YS51dGlsLkNvbGxlY3Rpb25zJFVubW9kaWZpYWJsZUNvbGxlY3Rpb24ZQgCAy173HgIAAUwAAWN0ABZMamF2YS91dGlsL0NvbGxlY3Rpb247eHBzcgATamF2YS51dGlsLkFycmF5TGlzdHiB0h2Zx2GdAwABSQAEc2l6ZXhwAAAAAHcEAAAAAHhxAH4AVXgAAAAAdACuUmVzb3VyY2UgW0hvc3Q6OV0gaXMgdW5yZWFjaGFibGU6IEhvc3QgOTogVW5hYmxlIHRvIHN0YXJ0IGluc3RhbmNlIGR1ZSB0byBVbmFibGUgdG8gc3RhcnQgIFZNOjJlNTRhYTQ5LWFlMzgtNDA1ZC1iMWZlLWYxNGIzMDA1M2FiNiBkdWUgdG8gZXJyb3IgaW4gZmluYWxpemVTdGFydCwgbm90IHJldHJ5aW5ndXEAfgAQAAAAFXNxAH4AEgAABGBxAH4AFHEAfgAVcQB-ABZzcQB-ABIAABHkcQB-ABRxAH4AFXEAfgAWc3EAfgAS_____nEAfgAZcQB-ABpxAH4AG3NxAH4AEgAAADlxAH4AGXEAfgAacQB-AB1zcQB-ABIAAAArcQB-AB9xAH4AIHEAfgAdc3EAfgASAAACXnEAfgAicQB-ACNxAH4AHXNxAH4AEgAAAGtxAH4AJXEAfgAmcQB-ACdzcQB-ABIAABKFcQB-ABRxAH4AFXEAfgAnc3EAfgASAAAAZnEAfgAqcQB-ACtxAH4ALHNxAH4AEgAAAipxAH4ALnEAfgAvcQB-ADBzcQB-ABIAAAAxcQB-ADJxAH4AM3EAfgA0c3EAfgASAAAAOHEAfgA2cQB-ADdxAH4AOHNxAH4AEgAAAGdxAH4AOnEAfgA3cQB-ADtzcQB-ABIAAAA1cQB-ADpxAH4AN3EAfgA9c3EAfgASAAAALnEAfgA_cQB-ADNxAH4ANHNxAH4AEgAAAfZxAH4ALnEAfgAvcQB-ADRzcQB-ABIAAAHXcQB-AEJxAH4AQ3EAfgA4c3EAfgASAAABBnEAfgBFcQB-AEZxAH4ANHNxAH4AEgAABHlxAH4ASHEAfgBJcQB-AEpzcQB-ABIAAAJncQB-AExxAH4ASXEAfgA0c3EAfgASAAAC6XEAfgBOcQB-AE9xAH4ANHEAfgBTeHNyABFqYXZhLmxhbmcuSW50ZWdlchLioKT3gYc4AgABSQAFdmFsdWV4cgAQamF2YS5sYW5nLk51bWJlcoaslR0LlOCLAgAAeHAAABC9c3EAfgBUAAAAAHcEAAAAAHgAAAAAAAAACXZyABNjb20uY2xvdWQuaG9zdC5Ib3N0AnjOn-BFiMkCAAB4cA
      2016-04-27 02:31:09,736 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160) (logid:6b2d4faa) Publish async job-1160 complete on message bus
      2016-04-27 02:31:09,736 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160) (logid:6b2d4faa) Wake up jobs related to job-1160
      2016-04-27 02:31:09,736 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160) (logid:6b2d4faa) Update db status for job-1160
      2016-04-27 02:31:09,737 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160) (logid:6b2d4faa) Wake up jobs joined with job-1160 and disjoin all subjobs created from job- 1160
      2016-04-27 02:31:09,747 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160) (logid:6b2d4faa) Done executing com.cloud.vm.VmWorkStart for job-1160
      2016-04-27 02:31:09,748 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160) (logid:6b2d4faa) Remove job-1160 from job monitoring
      
      Full Agent Error log
      2016-04-27 02:30:19,984 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:6b2d4faa) Request:Seq 9-332421947495286159:  { Cmd , MgmtId: 275619427298304, via: 9, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StartCommand":{"vm":{"id":252,"name":"r-252-VM","type":"DomainRouter","cpus":1,"minSpeed":500,"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.1.1.1/16 domain=cs2cloud.internal dns1=128.251.10.29 template=domP name=r-252-VM eth0ip=169.254.1.123 eth0mask=255.255.0.0 type=vpcrouter disable_rp_filter=true baremetalnotificationsecuritykey=0oLpL4swbL6Yu_xsuRdyjwmmyPHAU1V-iMpmMNKO00vNIP5bxronvhQZ_qehiEZ99Eo9avCHg9uLh1cbiz7pQA baremetalnotificationapikey=wEax_CyEaKZHn8ZkPBQLQaibjSWZ0OYJuEQA3l2RUA41GXZxaie9P6oQPeNlzjIGl-fDpKWp9MkAEQOJYvE4vA host=10.31.59.151 port=8080","enableHA":true,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"0Q5cib8VX0wIh1nvNsJktw","params":{},"uuid":"2e54aa49-ae38-405d-b1fe-f14b30053ab6","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"767e7794-1c87-4957-834a-a92eb711a15d","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"bf0515dd-fead-3151-b1a0-9d88c468583a","id":1,"poolType":"NetworkFilesystem","host":"mvdcvtb16.us.alcatel-lucent.com","path":"/mvdcvtb16/storage","port":2049,"url":"NetworkFilesystem://mvdcvtb16.us.alcatel-lucent.com/mvdcvtb16/storage/?ROLE=Primary&STOREUUID=bf0515dd-fead-3151-b1a0-9d88c468583a"}},"name":"ROOT-252","size":322954240,"path":"767e7794-1c87-4957-834a-a92eb711a15d","volumeId":252,"vmName":"r-252-VM","accountId":2,"format":"QCOW2","provisioningType":"THIN","id":252,"deviceId":0,"hypervisorType":"KVM"}},"diskSeq":0,"path":"767e7794-1c87-4957-834a-a92eb711a15d","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"mvdcvtb16.us.alcatel-lucent.com","volumeSize":"322954240"}}],"nics":[{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"pxeDisable":true,"nicUuid":"bf300ca0-afdb-4277-ac71-b7d0d041e29a","uuid":"1ec6ef5d-bed2-475a-9abb-122750fa8ea5","ip":"169.254.1.123","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:01:7b","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false}]},"hostIp":"10.100.100.12","executeInSequence":false,"wait":0}},{"com.cloud.agent.api.check.CheckSshCommand":{"ip":"169.254.1.123","port":3922,"interval":6,"retries":100,"name":"r-252-VM","wait":0}},{"com.cloud.agent.api.GetDomRVersionCmd":{"accessDetails":{"router.ip":"169.254.1.123","router.name":"r-252-VM"},"wait":0}},{"com.cloud.agent.api.PlugNicCommand":{"nic":{"deviceId":1,"networkRateMbps":200,"defaultNic":true,"pxeDisable":true,"nicUuid":"8a8486f8-9655-499b-9a78-bc76849254d3","uuid":"cdfc99be-4436-4740-afea-b99de3a436b4","ip":"10.31.59.187","netmask":"255.255.224.0","gateway":"10.31.32.1","mac":"06:6e:e8:00:00:41","broadcastType":"Vlan","type":"Public","broadcastUri":"vlan://0","isolationUri":"vlan://0","isSecurityGroupEnabled":false,"name":"cloudbr0"},"instanceName":"r-252-VM","vmType":"DomainRouter","wait":0}},{"com.cloud.agent.api.routing.IpAssocVpcCommand":{"ipAddresses":[{"accountId":2,"publicIp":"10.31.59.187","sourceNat":true,"add":true,"oneToOneNat":false,"firstIP":false,"broadcastUri":"vlan://0","vlanGateway":"10.31.32.1","vlanNetmask":"255.255.224.0","vifMacAddress":"06:6e:e8:00:00:41","networkRate":200,"trafficType":"Public","networkName":"cloudbr0","newNic":false}],"accessDetails":{"router.guest.ip":"10.31.59.187","zone.network.type":"Advanced","router.ip":"169.254.1.123","router.name":"r-252-VM"},"wait":0}},{"com.cloud.agent.api.routing.SetSourceNatCommand":{"ipAddress":{"accountId":2,"publicIp":"10.31.59.187","sourceNat":true,"add":true,"oneToOneNat":false,"firstIP":false,"broadcastUri":"vlan://0","vlanGateway":"10.31.32.1","vlanNetmask":"255.255.224.0","vifMacAddress":"06:6e:e8:00:00:41","networkRate":200,"trafficType":"Public","networkName":"cloudbr0","newNic":false},"add":true,"accessDetails":{"zone.network.type":"Advanced","router.ip":"169.254.1.123","router.name":"r-252-VM"},"wait":0}},{}] }
      2016-04-27 02:30:19,984 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:6b2d4faa) Processing command: com.cloud.agent.api.StartCommand
      2016-04-27 02:30:19,984 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:6b2d4faa) Looking for libvirtd connection at: qemu:///system
      2016-04-27 02:30:19,984 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:6b2d4faa) Trying to fetch storage pool bf0515dd-fead-3151-b1a0-9d88c468583a from libvirt
      2016-04-27 02:30:19,984 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:6b2d4faa) Looking for libvirtd connection at: qemu:///system
      2016-04-27 02:30:19,987 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:6b2d4faa) Succesfully refreshed pool bf0515dd-fead-3151-b1a0-9d88c468583a Capacity: 48088743936 Used: 15080095744 Available: 33008648192
      2016-04-27 02:30:19,987 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:6b2d4faa) Could not find volume 767e7794-1c87-4957-834a-a92eb711a15d: Storage volume not found: no storage vol with matching name '767e7794-1c87-4957-834a-a92eb711a15d'
      2016-04-27 02:30:19,987 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:6b2d4faa) Refreshing storage pool bf0515dd-fead-3151-b1a0-9d88c468583a
      2016-04-27 02:30:20,119 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:6b2d4faa) Found volume 767e7794-1c87-4957-834a-a92eb711a15d in storage pool bf0515dd-fead-3151-b1a0-9d88c468583a after refreshing the pool
      2016-04-27 02:30:20,135 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:6b2d4faa) Trying to fetch storage pool bf0515dd-fead-3151-b1a0-9d88c468583a from libvirt
      2016-04-27 02:30:20,135 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:6b2d4faa) Looking for libvirtd connection at: qemu:///system
      2016-04-27 02:30:20,137 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:6b2d4faa) Succesfully refreshed pool bf0515dd-fead-3151-b1a0-9d88c468583a Capacity: 48088743936 Used: 15080095744 Available: 33008648192
      2016-04-27 02:30:20,137 DEBUG [kvm.resource.OvsVifDriver] (agentRequest-Handler-2:null) (logid:6b2d4faa) plugging nic=[Nic:Control-169.254.1.123-null]
      2016-04-27 02:30:20,137 DEBUG [utils.script.Script] (agentRequest-Handler-2:null) (logid:6b2d4faa) Executing: /bin/bash -c ip route | grep 169.254.0.0/16
      2016-04-27 02:30:20,142 DEBUG [utils.script.Script] (agentRequest-Handler-2:null) (logid:6b2d4faa) Execution is successful.
      2016-04-27 02:30:20,143 DEBUG [utils.script.Script] (agentRequest-Handler-2:null) (logid:6b2d4faa) Executing: /bin/sh -c ovs-vsctl br-exists cloud0
      2016-04-27 02:30:20,151 DEBUG [utils.script.Script] (agentRequest-Handler-2:null) (logid:6b2d4faa) Execution is successful.
      2016-04-27 02:30:20,152 DEBUG [resource.wrapper.LibvirtStartCommandWrapper] (agentRequest-Handler-2:null) (logid:6b2d4faa) starting r-252-VM: <domain type='kvm'>
      <name>r-252-VM</name>
      <uuid>2e54aa49-ae38-405d-b1fe-f14b30053ab6</uuid>
      <description>Debian GNU/Linux 5.0 (64-bit)</description>
      <cpu></cpu><sysinfo type='smbios'>
      <system>
      <entry name='manufacturer'>Apache Software Foundation</entry>
      <entry name='product'>CloudStack KVM Hypervisor</entry>
      <entry name='uuid'>2e54aa49-ae38-405d-b1fe-f14b30053ab6</entry>
      </system>
      </sysinfo>
      <os>
      <type  arch='x86_64' machine='pc'>hvm</type>
      <boot dev='cdrom'/>
      <boot dev='hd'/>
      <smbios mode='sysinfo'/>
      </os>
      <on_reboot>restart</on_reboot>
      <on_poweroff>destroy</on_poweroff>
      <on_crash>destroy</on_crash>
      <memory>262144</memory>
      <devices>
      <memballoon model='none'/>
      </devices>
      <vcpu>1</vcpu>
      <features>
      <pae/>
      <apic/>
      <acpi/>
      </features>
      <cputune>
      <shares>500</shares>
      </cputune>
      <clock offset='utc'>
      <timer name='kvmclock' >
      </timer>
      </clock>
      <devices>
      <emulator>/usr/libexec/qemu-kvm</emulator>
      <interface type='bridge'>
      <source bridge='cloud0'/>
      <mac address='0e:00:a9:fe:01:7b'/>
      <model type='virtio'/>
      <virtualport type='openvswitch'>
      </virtualport>
      </interface>
      <console type='pty'>
      <target port='0'/>
      </console>
      <disk  device='disk' type='file'>
      <driver name='qemu' type='qcow2' cache='none' />
      <source file='/mnt/bf0515dd-fead-3151-b1a0-9d88c468583a/767e7794-1c87-4957-834a-a92eb711a15d'/>
      <target dev='vda' bus='virtio'/>
      <serial>767e77941c874957834a</serial></disk>
      <disk  device='cdrom' type='file'>
      <driver name='qemu' type='raw' cache='none' />
      <source file='/usr/share/cloudstack-common/vms/systemvm.iso'/>
      <target dev='hdc' bus='ide'/>
      </disk>
      <channel type='unix'>
      <source mode='bind' path='/var/lib/libvirt/qemu/r-252-VM.agent'/>
      <target type='virtio' name='r-252-VM.vport'/>
      <address type='virtio-serial'/>
      </channel>
      <serial type='pty'>
      <target port='0'/>
      </serial>
      <graphics type='vnc' autoport='yes' listen='10.100.100.12' passwd='0Q5cib8VX0wIh1nvNsJktw'/>
      <input type='tablet' bus='usb'/>
      </devices>
      </domain>
      2016-04-27 02:30:20,575 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) Executing: /usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/patchviasocket.pl -n r-252-VM -p %vpccidr=10.1.1.1/16%domain=cs2cloud.internal%dns1=128.251.10.29%template=domP%name=r-252-VM%eth0ip=169.254.1.123%eth0mask=255.255.0.0%type=vpcrouter%disable_rp_filter=true%baremetalnotificationsecuritykey=0oLpL4swbL6Yu_xsuRdyjwmmyPHAU1V-iMpmMNKO00vNIP5bxronvhQZ_qehiEZ99Eo9avCHg9uLh1cbiz7pQA%baremetalnotificationapikey=wEax_CyEaKZHn8ZkPBQLQaibjSWZ0OYJuEQA3l2RUA41GXZxaie9P6oQPeNlzjIGl-fDpKWp9MkAEQOJYvE4vA%host=10.31.59.151%port=8080
      2016-04-27 02:30:20,609 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) Execution is successful.
      2016-04-27 02:30:20,610 DEBUG [resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) Trying to connect to 169.254.1.123
      2016-04-27 02:30:22,139 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:null) (logid:ba7a5186) Processing command: com.cloud.agent.api.GetHostStatsCommand
      2016-04-27 02:30:23,615 DEBUG [resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) Could not connect to 169.254.1.123
      2016-04-27 02:30:28,616 DEBUG [resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) Trying to connect to 169.254.1.123
      2016-04-27 02:30:30,850 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:605aba90) Processing command: com.cloud.agent.api.GetVmStatsCommand
      2016-04-27 02:30:30,850 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:null) (logid:605aba90) Looking for libvirtd connection at: qemu:///system
      2016-04-27 02:30:31,621 DEBUG [resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) Could not connect to 169.254.1.123
      2016-04-27 02:30:36,622 DEBUG [resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) Unable to logon to 169.254.1.123
      2016-04-27 02:30:36,622 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) Executing: /usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/patchviasocket.pl -n r-252-VM -p %vpccidr=10.1.1.1/16%domain=cs2cloud.internal%dns1=128.251.10.29%template=domP%name=r-252-VM%eth0ip=169.254.1.123%eth0mask=255.255.0.0%type=vpcrouter%disable_rp_filter=true%baremetalnotificationsecuritykey=0oLpL4swbL6Yu_xsuRdyjwmmyPHAU1V-iMpmMNKO00vNIP5bxronvhQZ_qehiEZ99Eo9avCHg9uLh1cbiz7pQA%baremetalnotificationapikey=wEax_CyEaKZHn8ZkPBQLQaibjSWZ0OYJuEQA3l2RUA41GXZxaie9P6oQPeNlzjIGl-fDpKWp9MkAEQOJYvE4vA%host=10.31.59.151%port=8080
      2016-04-27 02:30:36,649 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) Execution is successful.
      2016-04-27 02:30:36,649 DEBUG [resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) Trying to connect to 169.254.1.123
      2016-04-27 02:30:36,650 DEBUG [resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) Could not connect to 169.254.1.123
      2016-04-27 02:30:41,650 DEBUG [resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) Trying to connect to 169.254.1.123
      2016-04-27 02:30:47,480 DEBUG [kvm.resource.LibvirtConnection] (Thread-1028:null) (logid:) Looking for libvirtd connection at: qemu:///system
      2016-04-27 02:30:47,481 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1028:null) (logid:) Found NFS storage pool bf0515dd-fead-3151-b1a0-9d88c468583a in libvirt, continuing
      2016-04-27 02:30:47,481 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1028:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/kvmheartbeat.sh -i mvdcvtb16.us.alcatel-lucent.com -p /mvdcvtb16/storage -m /mnt/bf0515dd-fead-3151-b1a0-9d88c468583a -h 10.100.100.12
      2016-04-27 02:30:47,511 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1028:null) (logid:) Execution is successful.
      2016-04-27 02:30:52,881 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:4136aaaa) Processing command: com.cloud.agent.api.GetVmStatsCommand
      2016-04-27 02:30:52,882 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:4136aaaa) Looking for libvirtd connection at: qemu:///system
      2016-04-27 02:30:56,682 DEBUG [resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) Could not connect to 169.254.1.123
      2016-04-27 02:31:01,682 DEBUG [resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) Unable to logon to 169.254.1.123
      2016-04-27 02:31:01,683 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) Executing: /usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/patchviasocket.pl -n r-252-VM -p %vpccidr=10.1.1.1/16%domain=cs2cloud.internal%dns1=128.251.10.29%template=domP%name=r-252-VM%eth0ip=169.254.1.123%eth0mask=255.255.0.0%type=vpcrouter%disable_rp_filter=true%baremetalnotificationsecuritykey=0oLpL4swbL6Yu_xsuRdyjwmmyPHAU1V-iMpmMNKO00vNIP5bxronvhQZ_qehiEZ99Eo9avCHg9uLh1cbiz7pQA%baremetalnotificationapikey=wEax_CyEaKZHn8ZkPBQLQaibjSWZ0OYJuEQA3l2RUA41GXZxaie9P6oQPeNlzjIGl-fDpKWp9MkAEQOJYvE4vA%host=10.31.59.151%port=8080
      2016-04-27 02:31:01,725 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) Execution is successful.
      2016-04-27 02:31:01,726 DEBUG [resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) Trying to connect to 169.254.1.123
      2016-04-27 02:31:01,726 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:6b2d4faa) Processing command: com.cloud.agent.api.check.CheckSshCommand
      2016-04-27 02:31:01,726 DEBUG [resource.wrapper.LibvirtOvsVpcRoutingPolicyConfigCommandWrapper] (agentRequest-Handler-2:null) (logid:6b2d4faa) Ping command port, 169.254.1.123:3922
      2016-04-27 02:31:01,726 DEBUG [resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) Trying to connect to 169.254.1.123
      2016-04-27 02:31:01,727 DEBUG [resource.wrapper.LibvirtOvsVpcRoutingPolicyConfigCommandWrapper] (agentRequest-Handler-2:null) (logid:6b2d4faa) Ping command port succeeded for vm r-252-VM
      2016-04-27 02:31:01,727 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:6b2d4faa) Processing command: com.cloud.agent.api.GetDomRVersionCmd
      2016-04-27 02:31:01,727 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) Executing: /usr/share/cloudstack-common/scripts/network/domr/router_proxy.sh get_template_version.sh 169.254.1.123
      2016-04-27 02:31:01,879 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) Execution is successful.
      2016-04-27 02:31:01,880 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:6b2d4faa) Processing command: com.cloud.agent.api.PlugNicCommand
      2016-04-27 02:31:01,880 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:6b2d4faa) Looking for libvirtd connection at: qemu:///system
      2016-04-27 02:31:01,882 DEBUG [kvm.resource.OvsVifDriver] (agentRequest-Handler-2:null) (logid:6b2d4faa) plugging nic=[Nic:Public-10.31.59.187-vlan://0]
      2016-04-27 02:31:01,882 DEBUG [kvm.resource.OvsVifDriver] (agentRequest-Handler-2:null) (logid:6b2d4faa) creating a vlan dev and bridge for public traffic per traffic label cloudbr0
      2016-04-27 02:31:01,985 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:6b2d4faa) Processing command: com.cloud.agent.api.routing.IpAssocVpcCommand
      2016-04-27 02:31:01,985 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:6b2d4faa) Looking for libvirtd connection at: qemu:///system
      2016-04-27 02:31:01,987 DEBUG [resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) Transforming com.cloud.agent.api.routing.IpAssocVpcCommand to ConfigItems
      2016-04-27 02:31:02,224 DEBUG [resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) Processing FileConfigItem, copying 231 characters to ip_associations.json took 237ms
      2016-04-27 02:31:02,224 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) Executing: /usr/share/cloudstack-common/scripts/network/domr/router_proxy.sh update_config.py 169.254.1.123 ip_associations.json
      2016-04-27 02:31:03,134 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) Exit value is 1
      2016-04-27 02:31:03,134 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) [INFO] update_config.py :: Processing incoming file => ip_associations.json[INFO] Processing JSON file ip_associations.jsonTraceback (most recent call last):  File "/opt/cloud/bin/update_config.py", line 140, in <module>    process_file()  File "/opt/cloud/bin/update_config.py", line 52, in process_file    qf.load(None)  File "/opt/cloud/bin/merge.py", line 258, in load    proc = updateDataBag(self)  File "/opt/cloud/bin/merge.py", line 91, in __init__    self.process()  File "/opt/cloud/bin/merge.py", line 103, in process    dbag = self.processIP(self.db.getDataBag())  File "/opt/cloud/bin/merge.py", line 190, in processIP    dbag = cs_ip.merge(dbag, ip)  File "/opt/cloud/bin/cs_ip.py", line 32, in merge    ip['device'] = 'eth' + str(ip['nic_dev_id'])KeyError: 'nic_dev_id'
      2016-04-27 02:31:03,135 DEBUG [resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-2:null) (logid:6b2d4faa) Processing ScriptConfigItem, executing update_config.py ip_associations.json took 911ms
      2016-04-27 02:31:03,135 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:6b2d4faa) Seq 9-332421947495286159:  { Ans: , MgmtId: 275619427298304, via: 9, Ver: v1, Flags: 110, [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":252,"name":"r-252-VM","type":"DomainRouter","cpus":1,"minSpeed":500,"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.1.1.1/16 domain=cs2cloud.internal dns1=128.251.10.29 template=domP name=r-252-VM eth0ip=169.254.1.123 eth0mask=255.255.0.0 type=vpcrouter disable_rp_filter=true baremetalnotificationsecuritykey=0oLpL4swbL6Yu_xsuRdyjwmmyPHAU1V-iMpmMNKO00vNIP5bxronvhQZ_qehiEZ99Eo9avCHg9uLh1cbiz7pQA baremetalnotificationapikey=wEax_CyEaKZHn8ZkPBQLQaibjSWZ0OYJuEQA3l2RUA41GXZxaie9P6oQPeNlzjIGl-fDpKWp9MkAEQOJYvE4vA host=10.31.59.151 port=8080","enableHA":true,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"0Q5cib8VX0wIh1nvNsJktw","vncAddr":"10.100.100.12","params":{},"uuid":"2e54aa49-ae38-405d-b1fe-f14b30053ab6","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"767e7794-1c87-4957-834a-a92eb711a15d","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"bf0515dd-fead-3151-b1a0-9d88c468583a","id":1,"poolType":"NetworkFilesystem","host":"mvdcvtb16.us.alcatel-lucent.com","path":"/mvdcvtb16/storage","port":2049,"url":"NetworkFilesystem://mvdcvtb16.us.alcatel-lucent.com/mvdcvtb16/storage/?ROLE=Primary&STOREUUID=bf0515dd-fead-3151-b1a0-9d88c468583a"}},"name":"ROOT-252","size":322954240,"path":"767e7794-1c87-4957-834a-a92eb711a15d","volumeId":252,"vmName":"r-252-VM","accountId":2,"format":"QCOW2","provisioningType":"THIN","id":252,"deviceId":0,"hypervisorType":"KVM"}},"diskSeq":0,"path":"767e7794-1c87-4957-834a-a92eb711a15d","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"mvdcvtb16.us.alcatel-lucent.com","volumeSize":"322954240"}}],"nics":[{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"pxeDisable":true,"nicUuid":"bf300ca0-afdb-4277-ac71-b7d0d041e29a","uuid":"1ec6ef5d-bed2-475a-9abb-122750fa8ea5","ip":"169.254.1.123","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:01:7b","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false}]},"result":true,"wait":0}},{"com.cloud.agent.api.check.CheckSshAnswer":{"result":true,"wait":0}},{"com.cloud.agent.api.GetDomRVersionAnswer":{"templateVersion":"Cloudstack Release 4.6.0 Mon Nov 9 11:21:06 UTC 2015","scriptsVersion":"e023565ed60d11c95133073ada75746e\n","result":true,"details":"Cloudstack Release 4.6.0 Mon Nov 9 11:21:06 UTC 2015&e023565ed60d11c95133073ada75746e\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 - failed: [INFO] update_config.py :: Processing incoming file => ip_associations.json[INFO] Processing JSON file ip_associations.jsonTraceback (most recent call last):  File \"/opt/cloud/bin/update_config.py\", line 140, in <module>    process_file()  File \"/opt/cloud/bin/update_config.py\", line 52, in process_file    qf.load(None)  File \"/opt/cloud/bin/merge.py\", line 258, in load    proc = updateDataBag(self)  File \"/opt/cloud/bin/merge.py\", line 91, in __init__    self.process()  File \"/opt/cloud/bin/merge.py\", line 103, in process    dbag = self.processIP(self.db.getDataBag())  File \"/opt/cloud/bin/merge.py\", line 190, in processIP    dbag = cs_ip.merge(dbag, ip)  File \"/opt/cloud/bin/cs_ip.py\", line 32, in merge    ip['device'] = 'eth' + str(ip['nic_dev_id'])KeyError: 'nic_dev_id'"],"result":false,"wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"Stopped by previous failure","wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"Stopped by previous failure","wait":0}}] }
      2016-04-27 02:31:03,207 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:6b2d4faa) Request:Seq 9-332421947495286162:  { Cmd , MgmtId: 275619427298304, via: 9, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"r-252-VM","wait":0}}] }
      2016-04-27 02:31:03,207 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:6b2d4faa) Processing command: com.cloud.agent.api.StopCommand
      2016-04-27 02:31:03,208 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:6b2d4faa) Looking for libvirtd connection at: qemu:///system
      2016-04-27 02:31:03,214 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-4:null) (logid:6b2d4faa) Executing: /usr/share/cloudstack-common/scripts/vm/network/security_group.py destroy_network_rules_for_vm --vmname r-252-VM --vif vnet5
      2016-04-27 02:31:03,378 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-4:null) (logid:6b2d4faa) Execution is successful.
      2016-04-27 02:31:03,378 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-4:null) (logid:6b2d4faa) Try to stop the vm at first
      2016-04-27 02:31:07,203 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:null) (logid:e0ab7a4d) Processing command: com.cloud.agent.api.GetHostStatsCommand
      2016-04-27 02:31:09,384 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-4:null) (logid:6b2d4faa) successfully shut down vm r-252-VM
      2016-04-27 02:31:09,384 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:6b2d4faa) Seq 9-332421947495286162:  { Ans: , MgmtId: 275619427298304, via: 9, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
      2016-04-27 02:31:09,444 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:6b2d4faa) Request:Seq 9-332421947495286163:  { Cmd , MgmtId: 275619427298304, via: 9, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"r-252-VM","wait":0}}] }
      2016-04-27 02:31:09,444 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:6b2d4faa) Processing command: com.cloud.agent.api.StopCommand
      2016-04-27 02:31:09,444 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:null) (logid:6b2d4faa) Looking for libvirtd connection at: qemu:///system
      2016-04-27 02:31:09,445 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:null) (logid:6b2d4faa) Can not find KVM connection for Instance: r-252-VM, continuing.
      2016-04-27 02:31:09,445 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:null) (logid:6b2d4faa) Looking for libvirtd connection at: lxc:///
      2016-04-27 02:31:09,446 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:null) (logid:6b2d4faa) Can not find LXC connection for Instance: r-252-VM, continuing.
      2016-04-27 02:31:09,446 WARN  [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:null) (logid:6b2d4faa) Can not find a connection for Instance r-252-VM. Assuming the default connection.
      2016-04-27 02:31:09,446 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:null) (logid:6b2d4faa) Looking for libvirtd connection at: qemu:///system
      2016-04-27 02:31:09,447 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) (logid:6b2d4faa) Failed to get dom xml: org.libvirt.LibvirtException: Domain not found: no domain with matching name 'r-252-VM'
      2016-04-27 02:31:09,448 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) (logid:6b2d4faa) Failed to get dom xml: org.libvirt.LibvirtException: Domain not found: no domain with matching name 'r-252-VM'
      2016-04-27 02:31:09,448 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) (logid:6b2d4faa) Failed to get dom xml: org.libvirt.LibvirtException: Domain not found: no domain with matching name 'r-252-VM'
      2016-04-27 02:31:09,448 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) (logid:6b2d4faa) Executing: /usr/share/cloudstack-common/scripts/vm/network/security_group.py destroy_network_rules_for_vm --vmname r-252-VM
      2016-04-27 02:31:09,609 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) (logid:6b2d4faa) Execution is successful.
      2016-04-27 02:31:09,610 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) (logid:6b2d4faa) Try to stop the vm at first
      2016-04-27 02:31:09,610 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) (logid:6b2d4faa) VM r-252-VM doesn't exist, no need to stop it
      2016-04-27 02:31:09,610 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:6b2d4faa) Seq 9-332421947495286163:  { Ans: , MgmtId: 275619427298304, via: 9, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
      2016-04-27 02:31:12,350 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:13e0ca62) Processing command: com.cloud.agent.api.GetStorageStatsCommand
      2016-04-27 02:31:12,350 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:13e0ca62) Trying to fetch storage pool bf0515dd-fead-3151-b1a0-9d88c468583a from libvirt
      2016-04-27 02:31:12,350 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:13e0ca62) Looking for libvirtd connection at: qemu:///system
      2016-04-27 02:31:12,352 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:13e0ca62) Asking libvirt to refresh storage pool bf0515dd-fead-3151-b1a0-9d88c468583a
      2016-04-27 02:31:12,513 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:13e0ca62) Succesfully refreshed pool bf0515dd-fead-3151-b1a0-9d88c468583a Capacity: 48088743936 Used: 15092678656 Available: 32996065280
      2016-04-27 02:31:12,727 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/network/security_group.py get_rule_logs_for_vms
      2016-04-27 02:31:12,858 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Execution is successful.
      2016-04-27 02:31:12,858 DEBUG [kvm.resource.LibvirtConnection] (UgentTask-5:null) (logid:) Looking for libvirtd connection at: qemu:///system
      2016-04-27 02:31:12,860 DEBUG [cloud.agent.Agent] (UgentTask-5:null) (logid:) Sending ping: Seq 9-1003:  { Cmd , MgmtId: -1, via: 9, Ver: v1, Flags: 11, [{"com.cloud.agent.api.PingRoutingWithNwGroupsCommand":{"newGroupStates":{},"_hostVmStateReport":{"i-2-247-VM":{"state":"PowerOn","host":"ovs-2.mvdcvtb16.us.alcatel-lucent.com"},"s-232-VM":{"state":"PowerOn","host":"ovs-2.mvdcvtb16.us.alcatel-lucent.com"}},"_gatewayAccessible":true,"_vnetAccessible":true,"hostType":"Routing","hostId":9,"wait":0}}] }
      2016-04-27 02:31:12,895 DEBUG [cloud.agent.Agent] (Agent-Handler-3:null) (logid:95ee606b) Received response: Seq 9-1003:  { Ans: , MgmtId: 275619427298560, via: 9, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.PingAnswer":{"_command":{"hostType":"Routing","hostId":9,"wait":0},"result":true,"wait":0}}] }
      
      Full Management Server Error log
      2016-04-27 02:31:09,243 DEBUG [o.s.b.f.s.DefaultListableBeanFactory] (catalina-exec-18:ctx-f74a2364 ctx-a6b6f0f5) (logid:811ff82e) Returning cached instance of singleton bean 'networkModelImpl'
      2016-04-27 02:31:09,243 DEBUG [o.s.b.f.a.InjectionMetadata] (catalina-exec-18:ctx-f74a2364 ctx-a6b6f0f5) (logid:811ff82e) Processing injected method of bean 'org.apache.cloudstack.api.command.user.job.QueryAsyncJobResultCmd': AutowiredFieldElement for public org.apache.cloudstack.alert.AlertService org.apache.cloudstack.api.BaseCmd._alertSvc
      2016-04-27 02:31:09,243 DEBUG [o.s.b.f.s.DefaultListableBeanFactory] (catalina-exec-18:ctx-f74a2364 ctx-a6b6f0f5) (logid:811ff82e) Returning cached instance of singleton bean 'alertManagerImpl'
      2016-04-27 02:31:09,243 DEBUG [o.s.b.f.a.InjectionMetadata] (catalina-exec-18:ctx-f74a2364 ctx-a6b6f0f5) (logid:811ff82e) Processing injected method of bean 'org.apache.cloudstack.api.command.user.job.QueryAsyncJobResultCmd': AutowiredFieldElement for public com.cloud.utils.db.UUIDManager org.apache.cloudstack.api.BaseCmd._uuidMgr
      2016-04-27 02:31:09,243 DEBUG [o.s.b.f.s.DefaultListableBeanFactory] (catalina-exec-18:ctx-f74a2364 ctx-a6b6f0f5) (logid:811ff82e) Returning cached instance of singleton bean 'uUIDManagerImpl'
      2016-04-27 02:31:09,262 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-f74a2364 ctx-a6b6f0f5) (logid:811ff82e) ===END===  10.31.56.146 -- GET  command=queryAsyncJobResult&jobId=6b2d4faa-4dae-4785-bd5b-cd06696a84da&response=json&_=1461749506662
      2016-04-27 02:31:09,311 INFO  [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-31d90a22) (logid:a7da00ab) Begin cleanup expired async-jobs
      2016-04-27 02:31:09,316 INFO  [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-31d90a22) (logid:a7da00ab) End cleanup expired async-jobs
      2016-04-27 02:31:09,387 DEBUG [c.c.a.t.Request] (AgentManager-Handler-15:null) (logid:) Seq 9-332421947495286162: Processing:  { Ans: , MgmtId: 275619427298304, via: 9, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
      2016-04-27 02:31:09,387 DEBUG [c.c.a.t.Request] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Seq 9-332421947495286162: Received:  { Ans: , MgmtId: 275619427298304, via: 9(ovs-2.mvdcvtb16.us.alcatel-lucent.com), Ver: v1, Flags: 10, { StopAnswer } }
      2016-04-27 02:31:09,387 ERROR [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Failed to start instance VM[DomainRouter|r-252-VM]
      com.cloud.utils.exception.ExecutionException: Unable to start  VM:2e54aa49-ae38-405d-b1fe-f14b30053ab6 due to error in finalizeStart, not retrying
              at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1084)
              at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4580)
              at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
              at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
              at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
              at java.lang.reflect.Method.invoke(Method.java:606)
              at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
              at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:4741)
              at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
              at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:554)
              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:502)
              at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
              at java.util.concurrent.FutureTask.run(FutureTask.java:262)
              at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
              at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
              at java.lang.Thread.run(Thread.java:745)
      2016-04-27 02:31:09,396 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Cleaning up resources for the vm VM[DomainRouter|r-252-VM] in Starting state
      2016-04-27 02:31:09,402 DEBUG [c.c.a.m.ClusteredAgentAttache] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Seq 9-332421947495286163: Forwarding Seq 9-332421947495286163:  { Cmd , MgmtId: 275619427298304, via: 9(ovs-2.mvdcvtb16.us.alcatel-lucent.com), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"r-252-VM","wait":0}}] } to 275619427298560
      2016-04-27 02:31:09,652 DEBUG [c.c.a.t.Request] (AgentManager-Handler-14:null) (logid:) Seq 9-332421947495286163: Processing:  { Ans: , MgmtId: 275619427298304, via: 9, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
      2016-04-27 02:31:09,652 DEBUG [c.c.a.t.Request] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Seq 9-332421947495286163: Received:  { Ans: , MgmtId: 275619427298304, via: 9(ovs-2.mvdcvtb16.us.alcatel-lucent.com), Ver: v1, Flags: 10, { StopAnswer } }
      2016-04-27 02:31:09,669 DEBUG [c.c.n.g.ControlNetworkGuru] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Released nic: NicProfile[715-252-null-null-null
      2016-04-27 02:31:09,686 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Successfully released network resources for the vm VM[DomainRouter|r-252-VM]
      2016-04-27 02:31:09,686 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Successfully cleanued up resources for the vm VM[DomainRouter|r-252-VM] in Starting state
      2016-04-27 02:31:09,704 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 9
      2016-04-27 02:31:09,709 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Hosts's actual total CPU: 23100 and CPU after applying overprovisioning: 23100
      2016-04-27 02:31:09,709 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Hosts's actual total RAM: 22296875008 and RAM after applying overprovisioning: 22296875008
      2016-04-27 02:31:09,709 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) release cpu from host: 9, old used: 1500,reserved: 0, actual total: 23100, total with overprovisioning: 23100; new used: 1000,reserved:0; movedfromreserved: false,moveToReserveredfalse
      2016-04-27 02:31:09,709 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) release mem from host: 9, old used: 1342177280,reserved: 0, total: 22296875008; new used: 1073741824,reserved:0; movedfromreserved: false,moveToReserveredfalse
      2016-04-27 02:31:09,716 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Invocation exception, caused by: com.cloud.exception.AgentUnavailableException: Resource [Host:9] is unreachable: Host 9: Unable to start instance due to Unable to start  VM:2e54aa49-ae38-405d-b1fe-f14b30053ab6 due to error in finalizeStart, not retrying
      2016-04-27 02:31:09,716 INFO  [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160 ctx-c31efe73) (logid:6b2d4faa) Rethrow exception com.cloud.exception.AgentUnavailableException: Resource [Host:9] is unreachable: Host 9: Unable to start instance due to Unable to start  VM:2e54aa49-ae38-405d-b1fe-f14b30053ab6 due to error in finalizeStart, not retrying
      2016-04-27 02:31:09,716 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160) (logid:6b2d4faa) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 252, job origin: 1159
      2016-04-27 02:31:09,716 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160) (logid:6b2d4faa) Unable to complete AsyncJobVO {id:1160, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAA_HQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AA5SZXN0YXJ0TmV0d29ya3QAP3JPMEFCWE55QUJGcVlYWmhMbXhoYm1jdVFtOXZiR1ZoYnMwZ2NvRFZuUHJ1QWdBQldnQUZkbUZzZFdWNGNBRXhw, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 275619427298304, completeMsid: null, lastUpdated: null, lastPolled: null, created: Wed Apr 27 02:30:18 PDT 2016}, job origin:1159
      com.cloud.exception.AgentUnavailableException: Resource [Host:9] is unreachable: Host 9: Unable to start instance due to Unable to start  VM:2e54aa49-ae38-405d-b1fe-f14b30053ab6 due to error in finalizeStart, not retrying
              at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1120)
              at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4580)
              at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
              at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
              at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
              at java.lang.reflect.Method.invoke(Method.java:606)
              at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
              at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:4741)
              at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
              at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:554)
              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:502)
              at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
              at java.util.concurrent.FutureTask.run(FutureTask.java:262)
              at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
              at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
              at java.lang.Thread.run(Thread.java:745)
      Caused by: com.cloud.utils.exception.ExecutionException: Unable to start  VM:2e54aa49-ae38-405d-b1fe-f14b30053ab6 due to error in finalizeStart, not retrying
              at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1084)
              at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4580)
              at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
              ... 18 more
      2016-04-27 02:31:09,734 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160) (logid:6b2d4faa) Complete async job-1160, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyAC1jb20uY2xvdWQuZXhjZXB0aW9uLkFnZW50VW5hdmFpbGFibGVFeGNlcHRpb24AAAAAVk1PdwIAAHhyADBjb20uY2xvdWQuZXhjZXB0aW9uLlJlc291cmNlVW5hdmFpbGFibGVFeGNlcHRpb24AAAAAVk1PfwIAAkoAA19pZEwABl9zY29wZXQAEUxqYXZhL2xhbmcvQ2xhc3M7eHIAImNvbS5jbG91ZC5leGNlcHRpb24uQ2xvdWRFeGNlcHRpb2556I4b8eRExwIAAkwAC2NzRXJyb3JDb2RldAATTGphdmEvbGFuZy9JbnRlZ2VyO0wABmlkTGlzdHQAFUxqYXZhL3V0aWwvQXJyYXlMaXN0O3hyABNqYXZhLmxhbmcuRXhjZXB0aW9u0P0fPho7HMQCAAB4cgATamF2YS5sYW5nLlRocm93YWJsZdXGNSc5d7jLAwAETAAFY2F1c2V0ABVMamF2YS9sYW5nL1Rocm93YWJsZTtMAA1kZXRhaWxNZXNzYWdldAASTGphdmEvbGFuZy9TdHJpbmc7WwAKc3RhY2tUcmFjZXQAHltMamF2YS9sYW5nL1N0YWNrVHJhY2VFbGVtZW50O0wAFHN1cHByZXNzZWRFeGNlcHRpb25zdAAQTGphdmEvdXRpbC9MaXN0O3hwc3IALGNvbS5jbG91ZC51dGlscy5leGNlcHRpb24uRXhlY3V0aW9uRXhjZXB0aW9uAAAAAFZNT34CAAFJAAtjc0Vycm9yQ29kZXhxAH4ABnEAfgAOdABkVW5hYmxlIHRvIHN0YXJ0ICBWTToyZTU0YWE0OS1hZTM4LTQwNWQtYjFmZS1mMTRiMzAwNTNhYjYgZHVlIHRvIGVycm9yIGluIGZpbmFsaXplU3RhcnQsIG5vdCByZXRyeWluZ3VyAB5bTGphdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudDsCRio8PP0iOQIAAHhwAAAAFXNyABtqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnRhCcWaJjbdhQIABEkACmxpbmVOdW1iZXJMAA5kZWNsYXJpbmdDbGFzc3EAfgAJTAAIZmlsZU5hbWVxAH4ACUwACm1ldGhvZE5hbWVxAH4ACXhwAAAEPHQAJmNvbS5jbG91ZC52bS5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsdAAeVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbC5qYXZhdAAQb3JjaGVzdHJhdGVTdGFydHNxAH4AEgAAEeRxAH4AFHEAfgAVcQB-ABZzcQB-ABL____-dAAkc3VuLnJlZmxlY3QuTmF0aXZlTWV0aG9kQWNjZXNzb3JJbXBsdAAdTmF0aXZlTWV0aG9kQWNjZXNzb3JJbXBsLmphdmF0AAdpbnZva2Uwc3EAfgASAAAAOXEAfgAZcQB-ABp0AAZpbnZva2VzcQB-ABIAAAArdAAoc3VuLnJlZmxlY3QuRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbHQAIURlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGwuamF2YXEAfgAdc3EAfgASAAACXnQAGGphdmEubGFuZy5yZWZsZWN0Lk1ldGhvZHQAC01ldGhvZC5qYXZhcQB-AB1zcQB-ABIAAABrdAAiY29tLmNsb3VkLnZtLlZtV29ya0pvYkhhbmRsZXJQcm94eXQAGlZtV29ya0pvYkhhbmRsZXJQcm94eS5qYXZhdAAPaGFuZGxlVm1Xb3JrSm9ic3EAfgASAAAShXEAfgAUcQB-ABVxAH4AJ3NxAH4AEgAAAGZ0ACBjb20uY2xvdWQudm0uVm1Xb3JrSm9iRGlzcGF0Y2hlcnQAGFZtV29ya0pvYkRpc3BhdGNoZXIuamF2YXQABnJ1bkpvYnNxAH4AEgAAAip0AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRzcQB-ABIAAAAxdAA-b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlJDF0ABtNYW5hZ2VkQ29udGV4dFJ1bm5hYmxlLmphdmF0AANydW5zcQB-ABIAAAA4dABCb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dCQxdAAaRGVmYXVsdE1hbmFnZWRDb250ZXh0LmphdmF0AARjYWxsc3EAfgASAAAAZ3QAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4AN3QAD2NhbGxXaXRoQ29udGV4dHNxAH4AEgAAADVxAH4AOnEAfgA3dAAOcnVuV2l0aENvbnRleHRzcQB-ABIAAAAudAA8b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlcQB-ADNxAH4ANHNxAH4AEgAAAfZxAH4ALnEAfgAvcQB-ADRzcQB-ABIAAAHXdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuRXhlY3V0b3JzJFJ1bm5hYmxlQWRhcHRlcnQADkV4ZWN1dG9ycy5qYXZhcQB-ADhzcQB-ABIAAAEGdAAfamF2YS51dGlsLmNvbmN1cnJlbnQuRnV0dXJlVGFza3QAD0Z1dHVyZVRhc2suamF2YXEAfgA0c3EAfgASAAAEeXQAJ2phdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvcnQAF1RocmVhZFBvb2xFeGVjdXRvci5qYXZhdAAJcnVuV29ya2Vyc3EAfgASAAACZ3QALmphdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvciRXb3JrZXJxAH4ASXEAfgA0c3EAfgASAAAC6XQAEGphdmEubGFuZy5UaHJlYWR0AAtUaHJlYWQuamF2YXEAfgA0c3IAJmphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVMaXN0_A8lMbXsjhACAAFMAARsaXN0cQB-AAt4cgAsamF2YS51dGlsLkNvbGxlY3Rpb25zJFVubW9kaWZpYWJsZUNvbGxlY3Rpb24ZQgCAy173HgIAAUwAAWN0ABZMamF2YS91dGlsL0NvbGxlY3Rpb247eHBzcgATamF2YS51dGlsLkFycmF5TGlzdHiB0h2Zx2GdAwABSQAEc2l6ZXhwAAAAAHcEAAAAAHhxAH4AVXgAAAAAdACuUmVzb3VyY2UgW0hvc3Q6OV0gaXMgdW5yZWFjaGFibGU6IEhvc3QgOTogVW5hYmxlIHRvIHN0YXJ0IGluc3RhbmNlIGR1ZSB0byBVbmFibGUgdG8gc3RhcnQgIFZNOjJlNTRhYTQ5LWFlMzgtNDA1ZC1iMWZlLWYxNGIzMDA1M2FiNiBkdWUgdG8gZXJyb3IgaW4gZmluYWxpemVTdGFydCwgbm90IHJldHJ5aW5ndXEAfgAQAAAAFXNxAH4AEgAABGBxAH4AFHEAfgAVcQB-ABZzcQB-ABIAABHkcQB-ABRxAH4AFXEAfgAWc3EAfgAS_____nEAfgAZcQB-ABpxAH4AG3NxAH4AEgAAADlxAH4AGXEAfgAacQB-AB1zcQB-ABIAAAArcQB-AB9xAH4AIHEAfgAdc3EAfgASAAACXnEAfgAicQB-ACNxAH4AHXNxAH4AEgAAAGtxAH4AJXEAfgAmcQB-ACdzcQB-ABIAABKFcQB-ABRxAH4AFXEAfgAnc3EAfgASAAAAZnEAfgAqcQB-ACtxAH4ALHNxAH4AEgAAAipxAH4ALnEAfgAvcQB-ADBzcQB-ABIAAAAxcQB-ADJxAH4AM3EAfgA0c3EAfgASAAAAOHEAfgA2cQB-ADdxAH4AOHNxAH4AEgAAAGdxAH4AOnEAfgA3cQB-ADtzcQB-ABIAAAA1cQB-ADpxAH4AN3EAfgA9c3EAfgASAAAALnEAfgA_cQB-ADNxAH4ANHNxAH4AEgAAAfZxAH4ALnEAfgAvcQB-ADRzcQB-ABIAAAHXcQB-AEJxAH4AQ3EAfgA4c3EAfgASAAABBnEAfgBFcQB-AEZxAH4ANHNxAH4AEgAABHlxAH4ASHEAfgBJcQB-AEpzcQB-ABIAAAJncQB-AExxAH4ASXEAfgA0c3EAfgASAAAC6XEAfgBOcQB-AE9xAH4ANHEAfgBTeHNyABFqYXZhLmxhbmcuSW50ZWdlchLioKT3gYc4AgABSQAFdmFsdWV4cgAQamF2YS5sYW5nLk51bWJlcoaslR0LlOCLAgAAeHAAABC9c3EAfgBUAAAAAHcEAAAAAHgAAAAAAAAACXZyABNjb20uY2xvdWQuaG9zdC5Ib3N0AnjOn-BFiMkCAAB4cA
      2016-04-27 02:31:09,736 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160) (logid:6b2d4faa) Publish async job-1160 complete on message bus
      2016-04-27 02:31:09,736 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160) (logid:6b2d4faa) Wake up jobs related to job-1160
      2016-04-27 02:31:09,736 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160) (logid:6b2d4faa) Update db status for job-1160
      2016-04-27 02:31:09,737 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160) (logid:6b2d4faa) Wake up jobs joined with job-1160 and disjoin all subjobs created from job- 1160
      2016-04-27 02:31:09,747 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160) (logid:6b2d4faa) Done executing com.cloud.vm.VmWorkStart for job-1160
      2016-04-27 02:31:09,748 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-10:ctx-1279b068 job-1159/job-1160) (logid:6b2d4faa) Remove job-1160 from job monitoring
      2016-04-27 02:31:09,759 WARN  [c.c.n.v.VpcManagerImpl] (API-Job-Executor-80:ctx-b49f0707 job-1159 ctx-d889f49a) (logid:6b2d4faa) Failed to start vpc [VPC [43-test] due to
      com.cloud.exception.AgentUnavailableException: Resource [Host:9] is unreachable: Host 9: Unable to start instance due to Unable to start  VM:2e54aa49-ae38-405d-b1fe-f14b30053ab6 due to error in finalizeStart, not retrying
              at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1120)
              at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4580)
              at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
              at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
              at java.lang.reflect.Method.invoke(Method.java:606)
              at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
              at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:4741)
              at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
              at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:554)
              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:502)
              at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
              at java.util.concurrent.FutureTask.run(FutureTask.java:262)
              at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
              at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
              at java.lang.Thread.run(Thread.java:745)
      Caused by: com.cloud.utils.exception.ExecutionException: Unable to start  VM:2e54aa49-ae38-405d-b1fe-f14b30053ab6 due to error in finalizeStart, not retrying
              at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1084)
              at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4580)
              at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
              ... 18 more
      2016-04-27 02:31:09,760 DEBUG [c.c.n.v.VpcManagerImpl] (API-Job-Executor-80:ctx-b49f0707 job-1159 ctx-d889f49a) (logid:6b2d4faa) Destroying vpc [VPC [43-test] that failed to start
      2016-04-27 02:31:09,760 DEBUG [c.c.n.v.VpcManagerImpl] (API-Job-Executor-80:ctx-b49f0707 job-1159 ctx-d889f49a) (logid:6b2d4faa) Destroying vpc [VPC [43-test]
      2016-04-27 02:31:09,761 DEBUG [c.c.n.v.VpcManagerImpl] (API-Job-Executor-80:ctx-b49f0707 job-1159 ctx-d889f49a) (logid:6b2d4faa) Updating VPC [VPC [43-test] with state Inactive as a part of vpc delete
      2016-04-27 02:31:09,773 DEBUG [c.c.n.v.VpcManagerImpl] (API-Job-Executor-80:ctx-b49f0707 job-1159 ctx-d889f49a) (logid:6b2d4faa) Shutting down vpc [VPC [43-test]
      2016-04-27 02:31:09,776 DEBUG [c.c.n.r.NetworkHelperImpl] (API-Job-Executor-80:ctx-b49f0707 job-1159 ctx-d889f49a) (logid:6b2d4faa) Attempting to destroy router 252
      2016-04-27 02:31:09,785 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-80:ctx-b49f0707 job-1159 ctx-d889f49a) (logid:6b2d4faa) Sync job-1161 execution on object VmWorkJobQueue.252
      2016-04-27 02:31:10,229 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-ede5e896) (logid:5b9128c0) ===START===  10.31.56.146 -- GET  command=queryAsyncJobResult&jobId=14d1e7f3-fd92-41c8-8e47-29ae1f90e68d&response=json&_=1461749507661
      2016-04-27 02:31:10,234 DEBUG [o.s.b.f.a.InjectionMetadata] (catalina-exec-18:ctx-ede5e896 ctx-358c2525) (logid:5b9128c0) Processing injected method of bean 'org.apache.cloudstack.api.command.user.job.QueryAsyncJobResultCmd': AutowiredFieldElement for public com.cloud.configuration.ConfigurationService org.apache.cloudstack.api.BaseCmd._configService
      2016-04-27 02:31:10,234 DEBUG [o.s.b.f.s.DefaultListableBeanFactory] (catalina-exec-18:ctx-ede5e896 ctx-358c2525) (logid:5b9128c0) Returning cached instance of singleton bean 'configurationManagerImpl'
      2016-04-27 02:31:10,234 DEBUG [o.s.b.f.a.InjectionMetadata] (catalina-exec-18:ctx-ede5e896 ctx-358c2525) (logid:5b9128c0) Processing injected method of bean 'org.apache.cloudstack.api.command.user.job.QueryAsyncJobResultCmd': AutowiredFieldElement for public com.cloud.user.AccountService org.apache.cloudstack.api.BaseCmd._accountService
      2016-04-27 02:31:10,234 DEBUG [o.s.b.f.s.DefaultListableBeanFactory] (catalina-exec-18:ctx-ede5e896 ctx-358c2525) (logid:5b9128c0) Returning cached instance of singleton bean 'accountManagerImpl'
      2016-04-27 02:31:10,234 DEBUG [o.s.b.f.a.InjectionMetadata] (catalina-exec-18:ctx-ede5e896 ctx-358c2525) (logid:5b9128c0) Processing injected method of bean 'org.apache.cloudstack.api.command.user.job.QueryAsyncJobResultCmd': AutowiredFieldElement for public com.cloud.vm.UserVmService org.apache.cloudstack.api.BaseCmd._userVmService
      2016-04-27 02:31:10,234 DEBUG [o.s.b.f.s.DefaultListableBeanFactory] (catalina-exec-18:ctx-ede5e896 ctx-358c2525) (logid:5b9128c0) Returning cached instance of singleton bean 'userVmManagerImpl'
      2016-04-27 02:31:10,234 DEBUG [o.s.b.f.a.InjectionMetadata] (catalina-exec-18:ctx-ede5e896 ctx-358c2525) (logid:5b9128c0) Processing injected method of bean 'org.apache.cloudstack.api.command.user.job.QueryAsyncJobResultCmd': AutowiredFieldElement for public com.cloud.server.ManagementService org.apache.cloudstack.api.BaseCmd._mgr
      2016-04-27 02:31:10,235 DEBUG [o.s.b.f.s.DefaultListableBeanFactory] (catalina-exec-18:ctx-ede5e896 ctx-358c2525) (logid:5b9128c0) Returning cached instance of singleton bean 'managementServerImpl'
      2016-04-27 02:31:10,235 DEBUG [o.s.b.f.a.InjectionMetadata] (catalina-exec-18:ctx-ede5e896 ctx-358c2525) (logid:5b9128c0) Processing injected method of bean 'org.apache.cloudstack.api.command.user.job.QueryAsyncJobResultCmd': AutowiredFieldElement for public com.cloud.storage.StorageService org.apache.cloudstack.api.BaseCmd._storageService
      2016-04-27 02:31:10,235 DEBUG [o.s.b.f.s.DefaultListableBeanFactory] (catalina-exec-18:ctx-ede5e896 ctx-358c2525) (logid:5b9128c0) Returning cached instance of singleton bean 'storageManagerImpl'
      2016-04-27 02:31:10,235 DEBUG [o.s.b.f.a.InjectionMetadata] (catalina-exec-18:ctx-ede5e896 ctx-358c2525) (logid:5b9128c0) Processing injected method of bean 'org.apache.cloudstack.api.command.user.job.QueryAsyncJobResultCmd': AutowiredFieldElement for public com.cloud.storage.VolumeApiService org.apache.cloudstack.api.BaseCmd._volumeService
      2016-04-27 02:31:10,235 DEBUG [o.s.b.f.s.DefaultListableBeanFactory] (catalina-exec-18:ctx-ede5e896 ctx-358c2525) (logid:5b9128c0) Returning cached instance of singleton bean 'volumeApiServiceImpl'
      2016-04-27 02:31:10,235 DEBUG [o.s.b.f.a.InjectionMetadata] (catalina-exec-18:ctx-ede5e896 ctx-358c2525) (logid:5b9128c0) Processing injected method of bean 'org.apache.cloudstack.api.command.user.job.QueryAsyncJobResultCmd': AutowiredFieldElement for public com.cloud.resource.ResourceService org.apache.cloudstack.api.BaseCmd._resourceService
      

      Let me know, if you need any more information from my side.

      Attachments

        Activity

          This comment will be Viewable by All Users Viewable by All Users
          Cancel

          People

            Unassigned Unassigned
            Prashanth Varma Manthena Mani Prashanth Varma Manthena

            Dates

              Created:
              Updated:

              Slack

                Issue deployment