[
https://issues.apache.org/jira/browse/CLOUDSTACK-9370?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Rajani Karuturi updated CLOUDSTACK-9370:
----------------------------------------
Fix Version/s: (was: 4.9.0)
4.10.0
> Failed to create VPC: Unable to start VPC VR (VM DomainRouter) due to error
> in finalizeStart, not retrying
> -----------------------------------------------------------------------------------------------------------
>
> Key: CLOUDSTACK-9370
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-9370
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the
> default.)
> Components: Virtual Router
> Affects Versions: 4.9.0
> Environment: Centos El7
> KVM
> OpenvSwitch (VLAN 0)
> NFS (primary/secondary)
> Reporter: Mani Prashanth Varma Manthena
> Priority: Critical
> Fix For: 4.10.0
>
>
> I am unable to create VPCs on latest cloudstack master due to the following
> error:
> {noformat:title=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
> {noformat}
> {noformat:title=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
> {noformat}
> {noformat:title=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}}]
> }
> {noformat}
> {noformat:title=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
> {noformat}
> Let me know, if you need any more information from my side.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
