cloudstack-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "vaibhav srivastava (JIRA)" <j...@apache.org>
Subject [jira] [Created] (CLOUDSTACK-4444) Can not create Vm using Cloud stack 4.2 and Xenserver6.0
Date Thu, 22 Aug 2013 09:04:51 GMT
vaibhav srivastava created CLOUDSTACK-4444:
----------------------------------------------

             Summary: Can not create Vm using Cloud stack 4.2 and Xenserver6.0
                 Key: CLOUDSTACK-4444
                 URL: https://issues.apache.org/jira/browse/CLOUDSTACK-4444
             Project: CloudStack
          Issue Type: Test
      Security Level: Public (Anyone can view this level - this is the default.)
          Components: Management Server, XenServer
    Affects Versions: 4.2.0
         Environment: Debian and Xenserver
            Reporter: vaibhav srivastava


I get following errors while trying to create VM using default centos template:
DEBUG [agent.transport.Request] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Seq 1-1674248267: Sending  { Cmd , MgmtId: 70787609328613, via: 1, Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"a83903a1-22fd-4fca-b7ed-3ab7ffa4d3ec","origUrl":"http://download.cloud.com/templates/4.2/systemvmtemplate-2013-06-12-master-xen.vhd.bz2","uuid":"4e10319f-0af1-11e3-ab63-4061864efbe5","id":1,"format":"VHD","accountId":1,"checksum":"fb1b6e032a160d86f2c28feb5add6d83","hvm":false,"displayText":"SystemVM Template (XenServer)","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"eb5eebc4-4cc9-3dcb-9a25-2cefca41e934","id":1,"poolType":"NetworkFilesystem","host":"192.168.1.2","path":"/export1/primary/primary123","port":2049}},"name":"routing-1","hypervisorType":"XenServer"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"ddf51060-6a3e-4b6f-8767-5b982d11b392","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"eb5eebc4-4cc9-3dcb-9a25-2cefca41e934","id":1,"poolType":"NetworkFilesystem","host":"192.168.1.2","path":"/export1/primary/primary123","port":2049}},"name":"ROOT-4","size":2101252608,"volumeId":5,"vmName":"r-4-VM","accountId":1,"format":"VHD","id":5,"hypervisorType":"None"}},"executeInSequence":false,"wait":0}}] }
DEBUG [agent.transport.Request] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Seq 1-1674248267: Executing:  { Cmd , MgmtId: 70787609328613, via: 1, Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"a83903a1-22fd-4fca-b7ed-3ab7ffa4d3ec","origUrl":"http://download.cloud.com/templates/4.2/systemvmtemplate-2013-06-12-master-xen.vhd.bz2","uuid":"4e10319f-0af1-11e3-ab63-4061864efbe5","id":1,"format":"VHD","accountId":1,"checksum":"fb1b6e032a160d86f2c28feb5add6d83","hvm":false,"displayText":"SystemVM Template (XenServer)","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"eb5eebc4-4cc9-3dcb-9a25-2cefca41e934","id":1,"poolType":"NetworkFilesystem","host":"192.168.1.2","path":"/export1/primary/primary123","port":2049}},"name":"routing-1","hypervisorType":"XenServer"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"ddf51060-6a3e-4b6f-8767-5b982d11b392","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"eb5eebc4-4cc9-3dcb-9a25-2cefca41e934","id":1,"poolType":"NetworkFilesystem","host":"192.168.1.2","path":"/export1/primary/primary123","port":2049}},"name":"ROOT-4","size":2101252608,"volumeId":5,"vmName":"r-4-VM","accountId":1,"format":"VHD","id":5,"hypervisorType":"None"}},"executeInSequence":false,"wait":0}}] }
DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-120:) Seq 1-1674248267: Executing request
DEBUG [xen.resource.XenServerStorageProcessor] (DirectAgent-120:) Succesfully created VDI: Uuid = 03f59c06-5704-4999-a4f0-50376a4618f4
DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-120:) Seq 1-1674248267: Response Received: 
DEBUG [agent.transport.Request] (DirectAgent-120:) Seq 1-1674248267: Processing:  { Ans: , MgmtId: 70787609328613, via: 1, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"newData":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"name":"ROOT-4","size":2097152000,"path":"03f59c06-5704-4999-a4f0-50376a4618f4","accountId":0,"id":0}},"result":true,"wait":0}}] }
DEBUG [agent.transport.Request] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Seq 1-1674248267: Received:  { Ans: , MgmtId: 70787609328613, via: 1, Ver: v1, Flags: 10, { CopyCmdAnswer } }
DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Boot Args for VM[DomainRouter|r-4-VM]:  template=domP name=r-4-VM eth0ip=192.168.1.44 eth0mask=255.255.255.0 gateway=192.168.1.1 domain=cs1cloud.internal dhcprange=192.168.1.1 eth1ip=169.254.3.72 eth1mask=255.255.0.0 type=dhcpsrvr disable_rp_filter=true dns1=203.241.132.34
DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Resending ipAssoc, port forwarding, load balancing rules as a part of Virtual router start
DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Found 0 firewall Egress rule(s) to apply as a part of domR VM[DomainRouter|r-4-VM] start.
DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Found0ip Aliases to revoke on the router as a part of dhcp configuration
DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Found0ip Aliases to apply on the router as a part of dhcp configuration
DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Reapplying dhcp entries as a part of domR VM[DomainRouter|r-4-VM] start...
DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Reapplying vm data (userData and metaData) entries as a part of domR VM[DomainRouter|r-4-VM] start...
DEBUG [agent.transport.Request] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Seq 1-1674248268: Sending  { Cmd , MgmtId: 70787609328613, via: 1, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StartCommand":{"vm":{"id":4,"name":"r-4-VM","bootloader":"PyGrub","type":"DomainRouter","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":134217728,"maxRam":134217728,"arch":"i686","os":"Debian GNU/Linux 7(32-bit)","bootArgs":" template=domP name=r-4-VM eth0ip=192.168.1.44 eth0mask=255.255.255.0 gateway=192.168.1.1 domain=cs1cloud.internal dhcprange=192.168.1.1 eth1ip=169.254.3.72 eth1mask=255.255.0.0 type=dhcpsrvr disable_rp_filter=true dns1=203.241.132.34","rebootOnCrash":false,"enableHA":true,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"a911ebdf5c7d3d03","params":{},"uuid":"199ee4b9-5c29-4854-b22f-d598aa39806c","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"ddf51060-6a3e-4b6f-8767-5b982d11b392","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"eb5eebc4-4cc9-3dcb-9a25-2cefca41e934","id":1,"poolType":"NetworkFilesystem","host":"192.168.1.2","path":"/export1/primary/primary123","port":2049}},"name":"ROOT-4","size":2097152000,"path":"03f59c06-5704-4999-a4f0-50376a4618f4","volumeId":5,"vmName":"r-4-VM","accountId":1,"format":"VHD","id":5,"hypervisorType":"XenServer"}},"diskSeq":0,"type":"ROOT"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"07f89bf6-5768-458b-aca1-876f4ba2549f","ip":"192.168.1.44","netmask":"255.255.255.0","gateway":"192.168.1.1","mac":"06:f3:ec:00:00:2b","dns1":"203.241.132.34","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":true},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"372b7c20-0b08-41cf-9ab4-d68ce403fe31","ip":"169.254.3.72","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:03:48","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false}]},"hostIp":"192.168.1.4","executeInSequence":false,"wait":0}},{"com.cloud.agent.api.check.CheckSshCommand":{"ip":"169.254.3.72","port":3922,"interval":6,"retries":100,"name":"r-4-VM","wait":0}},{"com.cloud.agent.api.GetDomRVersionCmd":{"accessDetails":{"router.ip":"169.254.3.72","router.name":"r-4-VM"},"wait":0}},{}] }
DEBUG [agent.transport.Request] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Seq 1-1674248268: Executing:  { Cmd , MgmtId: 70787609328613, via: 1, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StartCommand":{"vm":{"id":4,"name":"r-4-VM","bootloader":"PyGrub","type":"DomainRouter","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":134217728,"maxRam":134217728,"arch":"i686","os":"Debian GNU/Linux 7(32-bit)","bootArgs":" template=domP name=r-4-VM eth0ip=192.168.1.44 eth0mask=255.255.255.0 gateway=192.168.1.1 domain=cs1cloud.internal dhcprange=192.168.1.1 eth1ip=169.254.3.72 eth1mask=255.255.0.0 type=dhcpsrvr disable_rp_filter=true dns1=203.241.132.34","rebootOnCrash":false,"enableHA":true,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"a911ebdf5c7d3d03","params":{},"uuid":"199ee4b9-5c29-4854-b22f-d598aa39806c","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"ddf51060-6a3e-4b6f-8767-5b982d11b392","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"eb5eebc4-4cc9-3dcb-9a25-2cefca41e934","id":1,"poolType":"NetworkFilesystem","host":"192.168.1.2","path":"/export1/primary/primary123","port":2049}},"name":"ROOT-4","size":2097152000,"path":"03f59c06-5704-4999-a4f0-50376a4618f4","volumeId":5,"vmName":"r-4-VM","accountId":1,"format":"VHD","id":5,"hypervisorType":"XenServer"}},"diskSeq":0,"type":"ROOT"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"07f89bf6-5768-458b-aca1-876f4ba2549f","ip":"192.168.1.44","netmask":"255.255.255.0","gateway":"192.168.1.1","mac":"06:f3:ec:00:00:2b","dns1":"203.241.132.34","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":true},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"372b7c20-0b08-41cf-9ab4-d68ce403fe31","ip":"169.254.3.72","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:03:48","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false}]},"hostIp":"192.168.1.4","executeInSequence":false,"wait":0}},{"com.cloud.agent.api.check.CheckSshCommand":{"ip":"169.254.3.72","port":3922,"interval":6,"retries":100,"name":"r-4-VM","wait":0}},{"com.cloud.agent.api.GetDomRVersionCmd":{"accessDetails":{"router.ip":"169.254.3.72","router.name":"r-4-VM"},"wait":0}},{}] }
DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-127:) Seq 1-1674248268: Executing request
DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-127:) 1. The VM r-4-VM is in Starting state.
DEBUG [xen.resource.XenServer56FP1Resource] (DirectAgent-127:) Created VM 638ae85e-66a8-f5b5-66a3-053366983ece for r-4-VM
DEBUG [xen.resource.XenServer56FP1Resource] (DirectAgent-127:) PV args are -- quiet console=hvc0%template=domP%name=r-4-VM%eth0ip=192.168.1.44%eth0mask=255.255.255.0%gateway=192.168.1.1%domain=cs1cloud.internal%dhcprange=192.168.1.1%eth1ip=169.254.3.72%eth1mask=255.255.0.0%type=dhcpsrvr%disable_rp_filter=true%dns1=203.241.132.34
DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-127:) VBD 7587c03d-899b-5ed3-62b9-60a6b7d411b7 created for com.cloud.agent.api.to.DiskTO@1df867e
DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-127:) Creating VIF for r-4-VM on nic [Nic:Guest-192.168.1.44-vlan://untagged]
DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-127:) Created a vif fd3d6f87-ce4c-24c5-0dd1-da2173bbeb0e on 0
DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-127:) Creating VIF for r-4-VM on nic [Nic:Control-169.254.3.72-null]
DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-127:) already have a vif on dom0 for link local network
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377153982452
DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-127:) Created a vif c0e4ab97-ead4-ffd1-d6e4-d6098b5a8a7e on 1
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377153982452
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:) SeqA 2-281: Processing Seq 2-281:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:) SeqA 2-281: Sending Seq 2-281:  { Ans: , MgmtId: 70787609328613, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377153985453
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377153985453
DEBUG [cloud.server.StatsCollector] (StatsCollector-1:) HostStatsCollector is running...
DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-103:) Seq 1-1674248269: Executing request
DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-103:) Seq 1-1674248269: Response Received: 
DEBUG [agent.transport.Request] (StatsCollector-1:) Seq 1-1674248269: Received:  { Ans: , MgmtId: 70787609328613, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-127:) 2. The VM r-4-VM is in Running state.
DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-127:) Ping command port, 169.254.3.72:3922
DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-127:) Trying to connect to 169.254.3.72
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377153988451
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377153988451
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377153991452
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377153991452
DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:) Zone 1 is ready to launch secondary storage VM
DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:) Zone 1 is ready to launch console proxy
DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-23:) Ping from 1
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:) SeqA 2-282: Processing Seq 2-282:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:) SeqA 2-282: Sending Seq 2-282:  { Ans: , MgmtId: 70787609328613, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
DEBUG [cloud.server.StatsCollector] (StatsCollector-1:) StorageCollector is running...
DEBUG [agent.transport.Request] (StatsCollector-1:) Seq 3-963969062: Received:  { Ans: , MgmtId: 70787609328613, via: 3, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-120:) Seq 1-1674248270: Executing request
DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-140:) Seq 1-1674248196: Executing request
DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:) Found 0 routers to update status. 
DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:) Found 0 networks to update RvR status. 
DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:) Found 0 routers to update status. 
DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:) Found 0 networks to update RvR status. 
DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-140:) Seq 1-1674248196: Response Received: 
DEBUG [agent.transport.Request] (DirectAgent-140:) Seq 1-1674248196: Processing:  { Ans: , MgmtId: 70787609328613, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-120:) Seq 1-1674248270: Response Received: 
DEBUG [agent.transport.Request] (StatsCollector-1:) Seq 1-1674248270: Received:  { Ans: , MgmtId: 70787609328613, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377153994452
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377153994452
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:) Ping from 2
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-12:) Ping from 3
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377153997455
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377153997455
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:) SeqA 2-284: Processing Seq 2-284:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:) SeqA 2-284: Sending Seq 2-284:  { Ans: , MgmtId: 70787609328613, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:) Checking if any host reservation can be released ... 
DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:) Running Capacity Checker ... 
DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:) recalculating system capacity
DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:) Executing cpu/ram capacity update
DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:) Cannot release reservation, Found 4 VMs Running on host 1
DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:) Done running HostReservationReleaseChecker ... 
DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:) Found 4 VMs on host 1
DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:) Found 0 VM, not running on host 1
DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:) No need to calibrate cpu capacity, host:1 usedCpu: 2000 reservedCpu: 0
DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:) No need to calibrate memory capacity, host:1 usedMem: 2013265920 reservedMem: 0
DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:) Done executing cpu/ram capacity update
DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:) Executing storage capacity update
DEBUG [cloud.storage.StorageManagerImpl] (CapacityChecker:) Successfully set Capacity - 990585552896 for capacity type - 3 , DataCenterId - 1, HostOrPoolId - 1, PodId 1
DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:) Done executing storage capacity update
DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:) Executing capacity updates for public ip and Vlans
DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:) Done capacity updates for public ip and Vlans
DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:) Executing capacity updates for private ip
DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:) Done executing capacity updates for private ip
DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:) Done recalculating system capacity
DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:) Done running Capacity Checker ... 
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154000455
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154000455
DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-127:) Trying to connect to 169.254.3.72
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154003454
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154003454
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154006455
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154006455
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:) SeqA 2-285: Processing Seq 2-285:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:) SeqA 2-285: Sending Seq 2-285:  { Ans: , MgmtId: 70787609328613, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154009454
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154009454
DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-127:) Trying to connect to 169.254.3.72
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154012453
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154012453
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154015454
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154015454
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:) SeqA 2-286: Processing Seq 2-286:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:) SeqA 2-286: Sending Seq 2-286:  { Ans: , MgmtId: 70787609328613, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154018454
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154018454
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154021454
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154021454
DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:) Zone 1 is ready to launch secondary storage VM
DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:) Zone 1 is ready to launch console proxy
DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-127:) Trying to connect to 169.254.3.72
DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:) Found 0 routers to update status. 
DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:) Found 0 networks to update RvR status. 
DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:) Found 0 routers to update status. 
DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:) Found 0 networks to update RvR status. 
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154024453
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154024453
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===START===  127.0.0.1 -- GET  command=listVirtualMachines&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&listAll=true&page=1&pagesize=20&_=1377154026328
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===END===  127.0.0.1 -- GET  command=listVirtualMachines&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&listAll=true&page=1&pagesize=20&_=1377154026328
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154027449
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154027449
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:) SeqA 2-287: Processing Seq 2-287:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:) SeqA 2-287: Sending Seq 2-287:  { Ans: , MgmtId: 70787609328613, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:) Resetting hosts suitable for reconnect
DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:) Completed resetting hosts suitable for reconnect
DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:) Acquiring hosts for clusters already owned by this management server
DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:) Completed acquiring hosts for clusters already owned by this management server
DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:) Acquiring hosts for clusters not owned by any management server
DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:) Completed acquiring hosts for clusters not owned by any management server
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===START===  127.0.0.1 -- GET  command=listVirtualMachines&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&listAll=true&page=1&pagesize=20&_=1377154028995
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===END===  127.0.0.1 -- GET  command=listVirtualMachines&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&listAll=true&page=1&pagesize=20&_=1377154028995
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154030454
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154030454
DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-127:) Trying to connect to 169.254.3.72
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===START===  127.0.0.1 -- GET  command=listZones&id=e57d4242-fd87-4548-808a-3bde07bbafa8&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154032992
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===END===  127.0.0.1 -- GET  command=listZones&id=e57d4242-fd87-4548-808a-3bde07bbafa8&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154032992
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===START===  127.0.0.1 -- GET  command=listNetworks&id=f1447461-1e02-4a41-9c4f-2ea2b3710db6&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154033008
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===END===  127.0.0.1 -- GET  command=listNetworks&id=f1447461-1e02-4a41-9c4f-2ea2b3710db6&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154033008
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===START===  127.0.0.1 -- GET  command=listVirtualMachines&id=a9c49db3-5768-41d6-9cb0-ef4fcc03b2ce&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154033041
DEBUG [cloud.api.ApiServlet] (15517902@qtp-15384756-22:) ===END===  127.0.0.1 -- GET  command=listVirtualMachines&id=a9c49db3-5768-41d6-9cb0-ef4fcc03b2ce&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154033041
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===START===  127.0.0.1 -- GET  command=listOsTypes&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154033087
DEBUG [cloud.api.ApiServlet] (32622991@qtp-15384756-26:) ===START===  127.0.0.1 -- GET  command=listTags&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&resourceId=a9c49db3-5768-41d6-9cb0-ef4fcc03b2ce&resourceType=UserVm&listAll=true&_=1377154033109
DEBUG [cloud.api.ApiServlet] (32622991@qtp-15384756-26:) ===END===  127.0.0.1 -- GET  command=listTags&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&resourceId=a9c49db3-5768-41d6-9cb0-ef4fcc03b2ce&resourceType=UserVm&listAll=true&_=1377154033109
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===END===  127.0.0.1 -- GET  command=listOsTypes&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154033087
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154033510
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154033510
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154036523
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154036523
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:) SeqA 2-288: Processing Seq 2-288:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:) SeqA 2-288: Sending Seq 2-288:  { Ans: , MgmtId: 70787609328613, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===START===  127.0.0.1 -- GET  command=listZones&id=e57d4242-fd87-4548-808a-3bde07bbafa8&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154038140
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===END===  127.0.0.1 -- GET  command=listZones&id=e57d4242-fd87-4548-808a-3bde07bbafa8&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154038140
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===START===  127.0.0.1 -- GET  command=listNetworks&id=f1447461-1e02-4a41-9c4f-2ea2b3710db6&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154038153
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===END===  127.0.0.1 -- GET  command=listNetworks&id=f1447461-1e02-4a41-9c4f-2ea2b3710db6&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154038153
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===START===  127.0.0.1 -- GET  command=listVirtualMachines&id=a9c49db3-5768-41d6-9cb0-ef4fcc03b2ce&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154038180
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===END===  127.0.0.1 -- GET  command=listVirtualMachines&id=a9c49db3-5768-41d6-9cb0-ef4fcc03b2ce&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154038180
DEBUG [cloud.api.ApiServlet] (32622991@qtp-15384756-26:) ===START===  127.0.0.1 -- GET  command=listTags&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&resourceId=a9c49db3-5768-41d6-9cb0-ef4fcc03b2ce&resourceType=UserVm&listAll=true&_=1377154038235
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===START===  127.0.0.1 -- GET  command=listOsTypes&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154038220
DEBUG [cloud.api.ApiServlet] (32622991@qtp-15384756-26:) ===END===  127.0.0.1 -- GET  command=listTags&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&resourceId=a9c49db3-5768-41d6-9cb0-ef4fcc03b2ce&resourceType=UserVm&listAll=true&_=1377154038235
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===END===  127.0.0.1 -- GET  command=listOsTypes&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154038220
DEBUG [cloud.server.StatsCollector] (StatsCollector-1:) VmStatsCollector is running...
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===START===  127.0.0.1 -- GET  command=listVirtualMachines&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&listAll=true&page=1&pagesize=20&_=1377154039467
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===END===  127.0.0.1 -- GET  command=listVirtualMachines&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&listAll=true&page=1&pagesize=20&_=1377154039467
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154039576
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154039576
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154042574
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154042574
DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-127:) Trying to connect to 169.254.3.72
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154045579
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154045579
DEBUG [cloud.server.StatsCollector] (StatsCollector-3:) HostStatsCollector is running...
DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-72:) Seq 1-1674248271: Executing request
DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-72:) Seq 1-1674248271: Response Received: 
DEBUG [agent.transport.Request] (StatsCollector-3:) Seq 1-1674248271: Received:  { Ans: , MgmtId: 70787609328613, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-3:) SeqA 2-289: Processing Seq 2-289:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-3:) SeqA 2-289: Sending Seq 2-289:  { Ans: , MgmtId: 70787609328613, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154048581
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154048581
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154051579
DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:) Zone 1 is ready to launch secondary storage VM
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154051579
DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:) Zone 1 is ready to launch console proxy
DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-143:) Ping from 1
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:) SeqA 2-290: Processing Seq 2-290:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:) SeqA 2-290: Sending Seq 2-290:  { Ans: , MgmtId: 70787609328613, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-72:) Seq 1-1674248196: Executing request
DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:) Found 0 routers to update status. 
DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:) Found 0 networks to update RvR status. 
DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:) Found 0 routers to update status. 
DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:) Found 0 networks to update RvR status. 
DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-72:) Seq 1-1674248196: Response Received: 
DEBUG [agent.transport.Request] (DirectAgent-72:) Seq 1-1674248196: Processing:  { Ans: , MgmtId: 70787609328613, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
DEBUG [cloud.server.StatsCollector] (StatsCollector-1:) StorageCollector is running...
DEBUG [agent.transport.Request] (StatsCollector-1:) Seq 3-963969063: Received:  { Ans: , MgmtId: 70787609328613, via: 3, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-146:) Seq 1-1674248272: Executing request
DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-146:) Seq 1-1674248272: Response Received: 
DEBUG [agent.transport.Request] (StatsCollector-1:) Seq 1-1674248272: Received:  { Ans: , MgmtId: 70787609328613, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154054577
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154054577
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:) Ping from 2
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:) Ping from 3
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154057579
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154057579
DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-127:) Trying to connect to 169.254.3.72
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154060579
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154060579
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:) SeqA 2-292: Processing Seq 2-292:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:) SeqA 2-292: Sending Seq 2-292:  { Ans: , MgmtId: 70787609328613, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154063579
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154063579
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154066579
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154066579
DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-127:) Trying to connect to 169.254.3.72
DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-127:) Ping command port succeeded for vm r-4-VM
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154069580
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154069580
DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-127:) Seq 1-1674248268: Cancelling because one of the answers is false and it is stop on error.
DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-127:) Seq 1-1674248268: Response Received: 
DEBUG [agent.transport.Request] (DirectAgent-127:) Seq 1-1674248268: Processing:  { Ans: , MgmtId: 70787609328613, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":4,"name":"r-4-VM","bootloader":"PyGrub","type":"DomainRouter","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":134217728,"maxRam":134217728,"arch":"i686","os":"Debian GNU/Linux 7(32-bit)","bootArgs":" template=domP name=r-4-VM eth0ip=192.168.1.44 eth0mask=255.255.255.0 gateway=192.168.1.1 domain=cs1cloud.internal dhcprange=192.168.1.1 eth1ip=169.254.3.72 eth1mask=255.255.0.0 type=dhcpsrvr disable_rp_filter=true dns1=203.241.132.34","rebootOnCrash":false,"enableHA":true,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"a911ebdf5c7d3d03","params":{},"uuid":"199ee4b9-5c29-4854-b22f-d598aa39806c","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"ddf51060-6a3e-4b6f-8767-5b982d11b392","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"eb5eebc4-4cc9-3dcb-9a25-2cefca41e934","id":1,"poolType":"NetworkFilesystem","host":"192.168.1.2","path":"/export1/primary/primary123","port":2049}},"name":"ROOT-4","size":2097152000,"path":"03f59c06-5704-4999-a4f0-50376a4618f4","volumeId":5,"vmName":"r-4-VM","accountId":1,"format":"VHD","id":5,"hypervisorType":"XenServer"}},"diskSeq":0,"type":"ROOT"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"07f89bf6-5768-458b-aca1-876f4ba2549f","ip":"192.168.1.44","netmask":"255.255.255.0","gateway":"192.168.1.1","mac":"06:f3:ec:00:00:2b","dns1":"203.241.132.34","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":true},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"372b7c20-0b08-41cf-9ab4-d68ce403fe31","ip":"169.254.3.72","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:03:48","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":{"result":false,"details":"getDomRVersionCmd failed","wait":0}}] }
DEBUG [agent.transport.Request] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Seq 1-1674248268: Received:  { Ans: , MgmtId: 70787609328613, via: 1, Ver: v1, Flags: 10, { StartAnswer, CheckSshAnswer, GetDomRVersionAnswer } }
WARN  [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Unable to get the template/scripts version of router r-4-VM due to: getDomRVersionCmd failed
INFO  [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) The guru did not like the answers so stopping VM[DomainRouter|r-4-VM]
DEBUG [agent.transport.Request] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Seq 1-1674248273: Sending  { Cmd , MgmtId: 70787609328613, via: 1, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"r-4-VM","wait":0}}] }
DEBUG [agent.transport.Request] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Seq 1-1674248273: Executing:  { Cmd , MgmtId: 70787609328613, via: 1, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"r-4-VM","wait":0}}] }
DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-120:) Seq 1-1674248273: Executing request
DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-120:) 9. The VM r-4-VM is in Stopping state
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154072579
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154072579
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:) SeqA 2-293: Processing Seq 2-293:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:) SeqA 2-293: Sending Seq 2-293:  { Ans: , MgmtId: 70787609328613, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154075580
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154075580
DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-120:) 10. The VM r-4-VM is in Stopped state
DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-120:) Seq 1-1674248273: Response Received: 
DEBUG [agent.transport.Request] (DirectAgent-120:) Seq 1-1674248273: Processing:  { Ans: , MgmtId: 70787609328613, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"vncPort":0,"result":true,"details":"Stop VM r-4-VM Succeed","wait":0}}] }
DEBUG [agent.transport.Request] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Seq 1-1674248273: Received:  { Ans: , MgmtId: 70787609328613, via: 1, Ver: v1, Flags: 10, { StopAnswer } }
DEBUG [agent.manager.AgentManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Details from executing class com.cloud.agent.api.StopCommand: Stop VM r-4-VM Succeed
ERROR [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Failed to start instance VM[DomainRouter|r-4-VM]
com.cloud.utils.exception.ExecutionException: Unable to start VM[DomainRouter|r-4-VM] due to error in finalizeStart, not retrying
	at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:948)
	at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:575)
	at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.start(VirtualNetworkApplianceManagerImpl.java:2740)
	at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startVirtualRouter(VirtualNetworkApplianceManagerImpl.java:1872)
	at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startRouters(VirtualNetworkApplianceManagerImpl.java:1972)
	at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.deployVirtualRouterInGuestNetwork(VirtualNetworkApplianceManagerImpl.java:1950)
	at com.cloud.network.element.VirtualRouterElement.prepare(VirtualRouterElement.java:221)
	at com.cloud.network.NetworkManagerImpl.prepareElement(NetworkManagerImpl.java:2026)
	at com.cloud.network.NetworkManagerImpl.prepareNic(NetworkManagerImpl.java:2155)
	at com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.java:2096)
	at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:883)
	at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:575)
	at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:227)
	at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
	at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3406)
	at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2966)
	at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2952)
	at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
	at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:420)
	at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158)
	at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:531)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
	at java.util.concurrent.FutureTask.run(FutureTask.java:166)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:679)
DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Cleaning up resources for the vm VM[DomainRouter|r-4-VM] in Starting state
DEBUG [agent.transport.Request] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Seq 1-1674248274: Sending  { Cmd , MgmtId: 70787609328613, via: 1, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"r-4-VM","wait":0}}] }
DEBUG [agent.transport.Request] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Seq 1-1674248274: Executing:  { Cmd , MgmtId: 70787609328613, via: 1, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"r-4-VM","wait":0}}] }
DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-141:) Seq 1-1674248274: Executing request
INFO  [xen.resource.CitrixResourceBase] (DirectAgent-141:) VM does not exist on XenServere34aecef-6b40-4f60-b061-4ee77ab75cd4
DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-141:) Seq 1-1674248274: Response Received: 
DEBUG [agent.transport.Request] (DirectAgent-141:) Seq 1-1674248274: Processing:  { Ans: , MgmtId: 70787609328613, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"vncPort":0,"result":true,"details":"VM does not exist","wait":0}}] }
DEBUG [agent.transport.Request] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Seq 1-1674248274: Received:  { Ans: , MgmtId: 70787609328613, via: 1, Ver: v1, Flags: 10, { StopAnswer } }
DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Successfully updated user statistics as a part of domR VM[DomainRouter|r-4-VM] reboot/stop
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking VirtualRouter to release Nic[9-4-f665e982-c850-4716-8ec7-d33725ae964e-192.168.1.44]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking Ovs to release Nic[9-4-f665e982-c850-4716-8ec7-d33725ae964e-192.168.1.44]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking SecurityGroupProvider to release Nic[9-4-f665e982-c850-4716-8ec7-d33725ae964e-192.168.1.44]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking VpcVirtualRouter to release Nic[9-4-f665e982-c850-4716-8ec7-d33725ae964e-192.168.1.44]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking NiciraNvp to release Nic[9-4-f665e982-c850-4716-8ec7-d33725ae964e-192.168.1.44]
DEBUG [network.element.NiciraNvpElement] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Checking if NiciraNvpElement can handle service Connectivity on network defaultGuestNetwork
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking MidoNetElement to release Nic[9-4-f665e982-c850-4716-8ec7-d33725ae964e-192.168.1.44]
DEBUG [network.element.MidoNetElement] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) release called with network: Ntwk[204|Guest|6] nic: NicProfile[9-4-f665e982-c850-4716-8ec7-d33725ae964e-192.168.1.44-vlan://untagged vm: VM[DomainRouter|r-4-VM]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking StratosphereSsp to release Nic[9-4-f665e982-c850-4716-8ec7-d33725ae964e-192.168.1.44]
ERROR [network.element.SspElement] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) ReservationContext was null for NicProfile[9-4-f665e982-c850-4716-8ec7-d33725ae964e-192.168.1.44-vlan://untagged Ntwk[204|Guest|6]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking InternalLbVm to release Nic[9-4-f665e982-c850-4716-8ec7-d33725ae964e-192.168.1.44]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking BareMetalDhcp to release Nic[9-4-f665e982-c850-4716-8ec7-d33725ae964e-192.168.1.44]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking BareMetalPxe to release Nic[9-4-f665e982-c850-4716-8ec7-d33725ae964e-192.168.1.44]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking BareMetalUserdata to release Nic[9-4-f665e982-c850-4716-8ec7-d33725ae964e-192.168.1.44]
DEBUG [network.guru.ControlNetworkGuru] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Released nic: NicProfile[10-4-null-null-null
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking VirtualRouter to release Nic[10-4-f665e982-c850-4716-8ec7-d33725ae964e-null]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking Ovs to release Nic[10-4-f665e982-c850-4716-8ec7-d33725ae964e-null]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking SecurityGroupProvider to release Nic[10-4-f665e982-c850-4716-8ec7-d33725ae964e-null]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking VpcVirtualRouter to release Nic[10-4-f665e982-c850-4716-8ec7-d33725ae964e-null]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking NiciraNvp to release Nic[10-4-f665e982-c850-4716-8ec7-d33725ae964e-null]
DEBUG [network.element.NiciraNvpElement] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Checking if NiciraNvpElement can handle service Connectivity on network null
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking MidoNetElement to release Nic[10-4-f665e982-c850-4716-8ec7-d33725ae964e-null]
DEBUG [network.element.MidoNetElement] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) release called with network: Ntwk[202|Control|3] nic: NicProfile[10-4-null-null-null vm: VM[DomainRouter|r-4-VM]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking StratosphereSsp to release Nic[10-4-f665e982-c850-4716-8ec7-d33725ae964e-null]
ERROR [network.element.SspElement] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) ReservationContext was null for NicProfile[10-4-null-null-null Ntwk[202|Control|3]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking InternalLbVm to release Nic[10-4-f665e982-c850-4716-8ec7-d33725ae964e-null]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking BareMetalDhcp to release Nic[10-4-f665e982-c850-4716-8ec7-d33725ae964e-null]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking BareMetalPxe to release Nic[10-4-f665e982-c850-4716-8ec7-d33725ae964e-null]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking BareMetalUserdata to release Nic[10-4-f665e982-c850-4716-8ec7-d33725ae964e-null]
DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Successfully released network resources for the vm VM[DomainRouter|r-4-VM]
DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Successfully cleanued up resources for the vm VM[DomainRouter|r-4-VM] in Starting state
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===START===  127.0.0.1 -- GET  command=listVirtualMachines&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&listAll=true&page=1&pagesize=20&_=1377154078497
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===END===  127.0.0.1 -- GET  command=listVirtualMachines&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&listAll=true&page=1&pagesize=20&_=1377154078497
DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 1
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154078602
DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Hosts's actual total CPU: 63984 and CPU after applying overprovisioning: 63984
DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Hosts's actual total RAM: 12049926336 and RAM after applying overprovisioning: 12049926144
DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) release cpu from host: 1, old used: 2000,reserved: 0, actual total: 63984, total with overprovisioning: 63984; new used: 1500,reserved:0; movedfromreserved: false,moveToReserveredfalse
DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) release mem from host: 1, old used: 2013265920,reserved: 0, total: 12049926144; new used: 1879048192,reserved:0; movedfromreserved: false,moveToReserveredfalse
INFO  [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Unable to contact resource.
com.cloud.exception.AgentUnavailableException: Resource [Host:1] is unreachable: Host 1: Unable to start instance due to Unable to start VM[DomainRouter|r-4-VM] due to error in finalizeStart, not retrying
	at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:981)
	at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:575)
	at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.start(VirtualNetworkApplianceManagerImpl.java:2740)
	at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startVirtualRouter(VirtualNetworkApplianceManagerImpl.java:1872)
	at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startRouters(VirtualNetworkApplianceManagerImpl.java:1972)
	at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.deployVirtualRouterInGuestNetwork(VirtualNetworkApplianceManagerImpl.java:1950)
	at com.cloud.network.element.VirtualRouterElement.prepare(VirtualRouterElement.java:221)
	at com.cloud.network.NetworkManagerImpl.prepareElement(NetworkManagerImpl.java:2026)
	at com.cloud.network.NetworkManagerImpl.prepareNic(NetworkManagerImpl.java:2155)
	at com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.java:2096)
	at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:883)
	at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:575)
	at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:227)
	at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
	at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3406)
	at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2966)
	at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2952)
	at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
	at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:420)
	at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158)
	at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:531)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
	at java.util.concurrent.FutureTask.run(FutureTask.java:166)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:679)
Caused by: com.cloud.utils.exception.ExecutionException: Unable to start VM[DomainRouter|r-4-VM] due to error in finalizeStart, not retrying
	at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:948)
	... 30 more
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154078602
DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Cleaning up resources for the vm VM[User|vm] in Starting state
DEBUG [agent.transport.Request] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Seq 1-1674248275: Sending  { Cmd , MgmtId: 70787609328613, via: 1, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"i-2-3-VM","wait":0}}] }
DEBUG [agent.transport.Request] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Seq 1-1674248275: Executing:  { Cmd , MgmtId: 70787609328613, via: 1, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"i-2-3-VM","wait":0}}] }
DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-18:) Seq 1-1674248275: Executing request
INFO  [xen.resource.CitrixResourceBase] (DirectAgent-18:) VM does not exist on XenServere34aecef-6b40-4f60-b061-4ee77ab75cd4
DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-18:) Seq 1-1674248275: Response Received: 
DEBUG [agent.transport.Request] (DirectAgent-18:) Seq 1-1674248275: Processing:  { Ans: , MgmtId: 70787609328613, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"vncPort":0,"result":true,"details":"VM does not exist","wait":0}}] }
DEBUG [agent.transport.Request] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Seq 1-1674248275: Received:  { Ans: , MgmtId: 70787609328613, via: 1, Ver: v1, Flags: 10, { StopAnswer } }
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Changing active number of nics for network id=204 on -1
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking VirtualRouter to release Nic[8-3-1e78463c-74ff-49b0-baa6-3fbd4895edf2-192.168.1.43]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking Ovs to release Nic[8-3-1e78463c-74ff-49b0-baa6-3fbd4895edf2-192.168.1.43]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking SecurityGroupProvider to release Nic[8-3-1e78463c-74ff-49b0-baa6-3fbd4895edf2-192.168.1.43]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking VpcVirtualRouter to release Nic[8-3-1e78463c-74ff-49b0-baa6-3fbd4895edf2-192.168.1.43]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking NiciraNvp to release Nic[8-3-1e78463c-74ff-49b0-baa6-3fbd4895edf2-192.168.1.43]
DEBUG [network.element.NiciraNvpElement] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Checking if NiciraNvpElement can handle service Connectivity on network defaultGuestNetwork
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking MidoNetElement to release Nic[8-3-1e78463c-74ff-49b0-baa6-3fbd4895edf2-192.168.1.43]
DEBUG [network.element.MidoNetElement] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) release called with network: Ntwk[204|Guest|6] nic: NicProfile[8-3-1e78463c-74ff-49b0-baa6-3fbd4895edf2-192.168.1.43-vlan://untagged vm: VM[User|vm]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking StratosphereSsp to release Nic[8-3-1e78463c-74ff-49b0-baa6-3fbd4895edf2-192.168.1.43]
ERROR [network.element.SspElement] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) ReservationContext was null for NicProfile[8-3-1e78463c-74ff-49b0-baa6-3fbd4895edf2-192.168.1.43-vlan://untagged Ntwk[204|Guest|6]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking InternalLbVm to release Nic[8-3-1e78463c-74ff-49b0-baa6-3fbd4895edf2-192.168.1.43]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking BareMetalDhcp to release Nic[8-3-1e78463c-74ff-49b0-baa6-3fbd4895edf2-192.168.1.43]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking BareMetalPxe to release Nic[8-3-1e78463c-74ff-49b0-baa6-3fbd4895edf2-192.168.1.43]
DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Asking BareMetalUserdata to release Nic[8-3-1e78463c-74ff-49b0-baa6-3fbd4895edf2-192.168.1.43]
DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Successfully released network resources for the vm VM[User|vm]
DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Successfully cleanued up resources for the vm VM[User|vm] in Starting state
DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Deploy avoids pods: [], clusters: [], hosts: [1]
DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_a3bb9853@503bc4
DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 536870912
DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Is ROOT volume READY (pool already allocated)?: No
DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 1
DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) The specified host is in avoid set
DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Cannnot deploy to specified host, returning.
DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 1
DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Hosts's actual total CPU: 63984 and CPU after applying overprovisioning: 63984
DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Hosts's actual total RAM: 12049926336 and RAM after applying overprovisioning: 12049926144
DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) release cpu from host: 1, old used: 1500,reserved: 0, actual total: 63984, total with overprovisioning: 63984; new used: 1000,reserved:0; movedfromreserved: false,moveToReserveredfalse
DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) release mem from host: 1, old used: 1879048192,reserved: 0, total: 12049926144; new used: 1342177280,reserved:0; movedfromreserved: false,moveToReserveredfalse
DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: null new host id: null host id before state transition: null
DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Successfully transitioned to start state for VM[User|vm] reservation id = 12d94372-03e5-4683-9651-22121577e30f
DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Trying to deploy VM, vm has dcId: 1 and podId: 1
DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Deploy avoids pods: [], clusters: [], hosts: [1]
DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Deploy avoids pods: [], clusters: [], hosts: [1]
DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_a3bb9853@503bc4
DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:null, requested cpu: 500, requested ram: 536870912
DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Is ROOT volume READY (pool already allocated)?: No
DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Searching resources only under specified Pod: 1
DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 1
DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Removing from the clusterId list these clusters from avoid set: []
DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Checking resources in Cluster: 1 under Pod: 1
DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ] FirstFitRoutingAllocator) Looking for hosts in dc: 1  pod:1  cluster:1
DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ] FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]]
DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ] FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]]
DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ] FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=512
DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ] FirstFitRoutingAllocator) Host name: localhost, hostId: 1 is in avoid set, skipping this and trying other available hosts
DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ] FirstFitRoutingAllocator) Host Allocator returning 0 suitable hosts
DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) No suitable hosts found
DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) No suitable hosts found under this Cluster: 1
DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Could not find suitable Deployment Destination for this VM under any clusters, returning. 
DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Searching resources only under specified Pod: 1
DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 1
DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Removing from the clusterId list these clusters from avoid set: [1]
DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) No clusters found after removing disabled clusters and clusters in avoid list, returning.
DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: null
DEBUG [cloud.vm.UserVmManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Destroying vm VM[User|vm] as it failed to create on Host with Id:null
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===START===  127.0.0.1 -- GET  command=listVirtualMachines&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&listAll=true&page=1&pagesize=20&_=1377154079362
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===END===  127.0.0.1 -- GET  command=listVirtualMachines&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&listAll=true&page=1&pagesize=20&_=1377154079362
DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) VM state transitted from :Stopped to Error with event: OperationFailedToErrorvm's original host id: null new host id: null host id before state transition: null
WARN  [apache.cloudstack.alerts] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ])  alertType:: 8 // dataCenterId:: 1 // podId:: 1 // clusterId:: null // message:: Failed to deploy Vm with Id: 3, on Host with Id: null
INFO  [user.vm.DeployVMCmd] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|vm]Scope=interface com.cloud.dc.DataCenter; id=1
INFO  [user.vm.DeployVMCmd] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Unable to create a deployment for VM[User|vm]
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|vm]Scope=interface com.cloud.dc.DataCenter; id=1
	at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:839)
	at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:575)
	at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:237)
	at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
	at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3406)
	at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2966)
	at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2952)
	at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
	at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:420)
	at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158)
	at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:531)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
	at java.util.concurrent.FutureTask.run(FutureTask.java:166)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:679)
DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-8:job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ]) Complete async job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ], jobStatus: 2, resultCode: 530, result: Error Code: 533 Error text: Unable to create a deployment for VM[User|vm]
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===START===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154081579
DEBUG [cloud.async.AsyncJobManagerImpl] (6896058@qtp-15384756-25:) Async job-8 = [ dd359f97-633c-4f2b-9457-08f4f3804f8d ] completed
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===END===  127.0.0.1 -- GET  command=queryAsyncJobResult&jobId=dd359f97-633c-4f2b-9457-08f4f3804f8d&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154081579
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===START===  127.0.0.1 -- GET  command=listVirtualMachines&id=a9c49db3-5768-41d6-9cb0-ef4fcc03b2ce&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154081598
DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:) Zone 1 is ready to launch secondary storage VM
DEBUG [cloud.api.ApiServlet] (6896058@qtp-15384756-25:) ===END===  127.0.0.1 -- GET  command=listVirtualMachines&id=a9c49db3-5768-41d6-9cb0-ef4fcc03b2ce&response=json&sessionkey=fO37iDQHg1fw5zBBqJ4bz7O9n7M%3D&_=1377154081598
DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:) Zone 1 is ready to launch console proxy
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:) SeqA 2-294: Processing Seq 2-294:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:) SeqA 2-294: Sending Seq 2-294:  { Ans: , MgmtId: 70787609328613, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:) Found 0 routers to update status. 
DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:) Found 0 networks to update RvR status. 
DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:) Found 0 routers to update status. 
DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:) Found 0 networks to update RvR status. 
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:) SeqA 2-295: Processing Seq 2-295:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:) SeqA 2-295: Sending Seq 2-295:  { Ans: , MgmtId: 70787609328613, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }


--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira

Mime
View raw message