Can you provide the output : run this command on your host: cat /etc/xensource/network.conf
regards sadhu -----Original Message----- From: Osay Osman Yuuni [mailto:[email protected]] Sent: 20 March 2014 17:15 To: [email protected] Subject: Issue with Instance Hi, I've instantiated a template and in the web UI I see it's running. When I try launching the console I get in the console window the following error "Access is denied for the console session. Please close the window and retry later". When I look at the vm through XenCenter I see that it's stopped. A few seconds later I see that it's stopped in the web UI as well. The following log snippet is from the management-server log. Can anyone spot why this is happening? I'm using XCP 1.6 as hypervisor. ============================================= 2014-03-20 13:29:42,856 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-122:null) Seq 1-212795908: Response Received: 2014-03-20 13:29:42,870 DEBUG [agent.transport.Request] (DirectAgent-122:null) Seq 1-212795908: Processing: { Ans: , MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 110, [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":3,"name":"i-3-3-VM","bootloader":"PyGrub","type":"User","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":536870912,"maxRam":536870912,"arch":"x86_64","os":"Red Hat Enterprise Linux 6.3 (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"e9eb6e0b9d6b16e6","params":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:0","hypervisortoolsversion":"xenserver61","Message.ReservedCapacityFreed.Flag":"false"},"uuid":"4ec09c46-21b6-473b-acc3-3f4d92a805bd","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"ee597d75-a959-4407-b941-300c821fdd78","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"ba737116-8aa6-3644-a595-383d4dc39ed3","id":2,"poolType":"NetworkFilesystem","host":"192.168.40.71","path":"/fs_nfs1","port":2049}},"name":"ROOT-3","size":53687091200,"path":"d9c1be75-1d09-4754-ba04-543fe9f8c5e9","volumeId":3,"vmName":"i-3-3-VM","accountId":3,"format":"VHD","id":3,"hypervisorType":"XenServer"}},"diskSeq":0,"type":"ROOT"},{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"ba1413d7-c9e8-4608-b59f-3247008db98f","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"ba737116-8aa6-3644-a595-383d4dc39ed3","id":2,"poolType":"NetworkFilesystem","host":"192.168.40.71","path":"/fs_nfs1","port":2049}},"name":"DATA-3","size":21474836480,"path":"fdc05c9b-3aba-4111-a207-7c72493bed2f","volumeId":4,"vmName":"i-3-3-VM","accountId":3,"format":"VHD","id":4,"hypervisorType":"XenServer"}},"diskSeq":1,"type":"DATADISK"},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"2d8069e0-a3b0-40ac-ac2e-4306a5a15c64","ip":"192.168.40.182","netmask":"255.255.255.0","gateway":"192.168.40.1","mac":"06:2c:2c:00:00:0b","dns1":"192.168.40.41","dns2":"192.168.40.42","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":true}]},"result":true,"wait":0}}] } 2014-03-20 13:29:42,870 DEBUG [agent.transport.Request] (Job-Executor-6:job-13 = [ a33879c5-8406-47ce-8758-23e461142188 ]) Seq 1-212795908: Received: { Ans: , MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 110, { StartAnswer } } 2014-03-20 13:29:42,872 DEBUG [agent.manager.AgentAttache] (DirectAgent-122:null) Seq 1-212795908: No more commands found 2014-03-20 13:29:43,063 DEBUG [network.security.SecurityGroupManagerImpl] (Job-Executor-6:job-13 = [ a33879c5-8406-47ce-8758-23e461142188 ]) Security Group Mgr v2: scheduling ruleset updates for 1 vms (unique=1), current queue size=0 2014-03-20 13:29:43,073 DEBUG [network.security.SecurityGroupManagerImpl] (Job-Executor-6:job-13 = [ a33879c5-8406-47ce-8758-23e461142188 ]) Security Group Mgr v2: done scheduling ruleset updates for 1 vms: num new jobs=1 num rows insert or updated=1 time taken=9 2014-03-20 13:29:43,092 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-6:job-13 = [ a33879c5-8406-47ce-8758-23e461142188 ]) VM state transitted from :Starting to Running with event: OperationSucceededvm's original host id: 1 new host id: 1 host id before state transition: 1 2014-03-20 13:29:43,102 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-6:job-13 = [ a33879c5-8406-47ce-8758-23e461142188 ]) Start completed for VM VM[User|TestVM] 2014-03-20 13:29:43,113 DEBUG [network.security.SecurityGroupManagerImpl] (SecGrp-Worker-4:null) SecurityGroupManager v2: sending ruleset update for vm i-3-3-VM:ingress num rules=0:egress num rules=0 num cidrs=0 sig=d41d8cd98f00b204e9800998ecf8427e 2014-03-20 13:29:43,130 DEBUG [agent.transport.Request] (SecGrp-Worker-4:null) Seq 1-212795909: Sending { Cmd , MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.SecurityGroupRulesCmd":{"guestIp":"192.168.40.182","vmName":"i-3-3-VM","guestMac":"06:2c:2c:00:00:0b","signature":"d41d8cd98f00b204e9800998ecf8427e","seqNum":5,"vmId":3,"msId":7063056740127,"ingressRuleSet":[],"egressRuleSet":[],"wait":0}}] } 2014-03-20 13:29:43,137 DEBUG [agent.transport.Request] (SecGrp-Worker-4:null) Seq 1-212795909: Executing: { Cmd , MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.SecurityGroupRulesCmd":{"guestIp":"192.168.40.182","vmName":"i-3-3-VM","guestMac":"06:2c:2c:00:00:0b","signature":"d41d8cd98f00b204e9800998ecf8427e","seqNum":5,"vmId":3,"msId":7063056740127,"ingressRuleSet":[],"egressRuleSet":[],"wait":0}}] } 2014-03-20 13:29:43,138 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-103:null) Seq 1-212795909: Executing request 2014-03-20 13:29:43,193 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-6:job-13 = [ a33879c5-8406-47ce-8758-23e461142188 ]) Complete async job-13 = [ a33879c5-8406-47ce-8758-23e461142188 ], jobStatus: 1, resultCode: 0, result: org.apache.cloudstack.api.response.UserVmResponse@1020b01c 2014-03-20 13:29:43,211 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-6:job-13 = [ a33879c5-8406-47ce-8758-23e461142188 ]) Done executing org.apache.cloudstack.api.command.user.vm.StartVMCmd for job-13 = [ a33879c5-8406-47ce-8758-23e461142188 ] 2014-03-20 13:29:43,310 WARN [xen.resource.CitrixResourceBase] (DirectAgent-103:null) Host 192.168.40.245 cannot do bridge firewalling 2014-03-20 13:29:43,311 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-103:null) Seq 1-212795909: Response Received: 2014-03-20 13:29:43,312 DEBUG [agent.transport.Request] (DirectAgent-103:null) Seq 1-212795909: Processing: { Ans: , MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 110, [{"com.cloud.agent.api.SecurityGroupRuleAnswer":{"logSequenceNumber":5,"vmId":3,"reason":"CANNOT_BRIDGE_FIREWALL","result":false,"details":"Host 192.168.40.245 cannot do bridge firewalling","wait":0}}] } 2014-03-20 13:29:43,317 DEBUG [network.security.SecurityGroupListener] (DirectAgent-103:null) Failed to program rule com.cloud.agent.api.SecurityGroupRuleAnswer into host 1 due to Host 192.168.40.245 cannot do bridge firewalling and updated jobs 2014-03-20 13:29:43,318 DEBUG [network.security.SecurityGroupListener] (DirectAgent-103:null) Not retrying security group rules for vm 3 on failure since host 1 cannot do bridge firewalling 2014-03-20 13:29:43,323 DEBUG [network.security.SecurityGroupListener] (DirectAgent-103:null) Failed to program rule com.cloud.agent.api.SecurityGroupRuleAnswer into host 1 due to Host 192.168.40.245 cannot do bridge firewalling and updated jobs 2014-03-20 13:29:43,323 DEBUG [network.security.SecurityGroupListener] (DirectAgent-103:null) Not retrying security group rules for vm 3 on failure since host 1 cannot do bridge firewalling 2014-03-20 13:29:43,323 DEBUG [agent.manager.AgentAttache] (DirectAgent-103:null) Seq 1-212795909: No more commands found 2014-03-20 13:29:44,651 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 2-2862: Processing Seq 2-2862: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] } 2014-03-20 13:29:44,669 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 2-2862: Sending Seq 2-2862: { Ans: , MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } 2014-03-20 13:29:44,676 DEBUG [cloud.api.ApiServlet] (catalina-exec-3:null) ===START=== 10.29.128.147 -- GET command=queryAsyncJobResult&jobId=a33879c5-8406-47ce-8758-23e461142188&response=json&sessionkey=diGqWRPhshb4jEtEnA3%2Fb61qoXI%3D&_=1395314982758 2014-03-20 13:29:44,720 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-3:null) Async job-13 = [ a33879c5-8406-47ce-8758-23e461142188 ] completed 2014-03-20 13:29:44,742 DEBUG [cloud.api.ApiServlet] (catalina-exec-3:null) ===END=== 10.29.128.147 -- GET command=queryAsyncJobResult&jobId=a33879c5-8406-47ce-8758-23e461142188&response=json&sessionkey=diGqWRPhshb4jEtEnA3%2Fb61qoXI%3D&_=1395314982758 2014-03-20 13:29:44,813 DEBUG [cloud.api.ApiServlet] (catalina-exec-24:null) ===START=== 10.29.128.147 -- GET command=listZones&id=01239a63-b0ec-4064-90df-1da245ed6b8d&response=json&sessionkey=diGqWRPhshb4jEtEnA3%2Fb61qoXI%3D&_=1395314982883 2014-03-20 13:29:44,855 DEBUG [cloud.api.ApiServlet] (catalina-exec-24:null) ===END=== 10.29.128.147 -- GET command=listZones&id=01239a63-b0ec-4064-90df-1da245ed6b8d&response=json&sessionkey=diGqWRPhshb4jEtEnA3%2Fb61qoXI%3D&_=1395314982883 2014-03-20 13:29:44,908 DEBUG [cloud.api.ApiServlet] (catalina-exec-4:null) ===START=== 10.29.128.147 -- GET command=listNetworks&id=e41c255c-a814-4900-bec3-cee797bb02c3&response=json&sessionkey=diGqWRPhshb4jEtEnA3%2Fb61qoXI%3D&_=1395314982951 2014-03-20 13:29:45,009 DEBUG [cloud.api.ApiServlet] (catalina-exec-4:null) ===END=== 10.29.128.147 -- GET command=listNetworks&id=e41c255c-a814-4900-bec3-cee797bb02c3&response=json&sessionkey=diGqWRPhshb4jEtEnA3%2Fb61qoXI%3D&_=1395314982951 2014-03-20 13:29:45,068 DEBUG [cloud.api.ApiServlet] (catalina-exec-18:null) ===START=== 10.29.128.147 -- GET command=listVirtualMachines&id=4ec09c46-21b6-473b-acc3-3f4d92a805bd&response=json&sessionkey=diGqWRPhshb4jEtEnA3%2Fb61qoXI%3D&_=1395314983115 2014-03-20 13:29:45,149 DEBUG [cloud.api.ApiServlet] (catalina-exec-18:null) ===END=== 10.29.128.147 -- GET command=listVirtualMachines&id=4ec09c46-21b6-473b-acc3-3f4d92a805bd&response=json&sessionkey=diGqWRPhshb4jEtEnA3%2Fb61qoXI%3D&_=1395314983115 2014-03-20 13:29:45,253 DEBUG [cloud.api.ApiServlet] (catalina-exec-13:null) ===START=== 10.29.128.147 -- GET command=listOsTypes&response=json&sessionkey=diGqWRPhshb4jEtEnA3%2Fb61qoXI%3D&_=1395314983249 2014-03-20 13:29:45,281 DEBUG [cloud.api.ApiServlet] (catalina-exec-16:null) ===START=== 10.29.128.147 -- GET command=listTags&response=json&sessionkey=diGqWRPhshb4jEtEnA3%2Fb61qoXI%3D&resourceId=4ec09c46-21b6-473b-acc3-3f4d92a805bd&resourceType=UserVm&listAll=true&_=1395314983275 2014-03-20 13:29:45,309 DEBUG [cloud.api.ApiServlet] (catalina-exec-16:null) ===END=== 10.29.128.147 -- GET command=listTags&response=json&sessionkey=diGqWRPhshb4jEtEnA3%2Fb61qoXI%3D&resourceId=4ec09c46-21b6-473b-acc3-3f4d92a805bd&resourceType=UserVm&listAll=true&_=1395314983275 2014-03-20 13:29:45,747 DEBUG [cloud.api.ApiServlet] (catalina-exec-13:null) ===END=== 10.29.128.147 -- GET command=listOsTypes&response=json&sessionkey=diGqWRPhshb4jEtEnA3%2Fb61qoXI%3D&_=1395314983249 2014-03-20 13:29:49,650 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 2-2863: Processing Seq 2-2863: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] } 2014-03-20 13:29:49,664 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 2-2863: Sending Seq 2-2863: { Ans: , MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } 2014-03-20 13:29:54,651 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 2-2864: Processing Seq 2-2864: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] } 2014-03-20 13:29:54,666 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 2-2864: Sending Seq 2-2864: { Ans: , MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } 2014-03-20 13:29:59,439 DEBUG [cloud.api.ApiServlet] (catalina-exec-15:null) ===START=== 10.29.128.147 -- GET command=listVirtualMachines&details=nics&id=4ec09c46-21b6-473b-acc3-3f4d92a805bd&response=json&sessionkey=diGqWRPhshb4jEtEnA3%2Fb61qoXI%3D&_=1395314997504 2014-03-20 13:29:59,519 DEBUG [cloud.api.ApiServlet] (catalina-exec-15:null) ===END=== 10.29.128.147 -- GET command=listVirtualMachines&details=nics&id=4ec09c46-21b6-473b-acc3-3f4d92a805bd&response=json&sessionkey=diGqWRPhshb4jEtEnA3%2Fb61qoXI%3D&_=1395314997504 2014-03-20 13:29:59,652 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 2-2865: Processing Seq 2-2865: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] } 2014-03-20 13:29:59,671 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 2-2865: Sending Seq 2-2865: { Ans: , MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } 2014-03-20 13:30:01,478 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM 2014-03-20 13:30:02,094 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy 2014-03-20 13:30:04,358 DEBUG [cloud.api.ApiServlet] (catalina-exec-25:null) ===START=== 10.29.128.147 -- GET command=listNics&response=json&sessionkey=diGqWRPhshb4jEtEnA3%2Fb61qoXI%3D&nicId=2d8069e0-a3b0-40ac-ac2e-4306a5a15c64&virtualmachineid=4ec09c46-21b6-473b-acc3-3f4d92a805bd&_=1395315002412 2014-03-20 13:30:04,503 DEBUG [cloud.api.ApiServlet] (catalina-exec-25:null) ===END=== 10.29.128.147 -- GET command=listNics&response=json&sessionkey=diGqWRPhshb4jEtEnA3%2Fb61qoXI%3D&nicId=2d8069e0-a3b0-40ac-ac2e-4306a5a15c64&virtualmachineid=4ec09c46-21b6-473b-acc3-3f4d92a805bd&_=1395315002412 2014-03-20 13:30:04,634 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status. 2014-03-20 13:30:04,639 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status. 2014-03-20 13:30:08,656 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Ping from 2 2014-03-20 13:30:08,779 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:null) Ping from 3 2014-03-20 13:30:09,654 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-3:null) SeqA 2-2867: Processing Seq 2-2867: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] } 2014-03-20 13:30:09,667 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-3:null) SeqA 2-2867: Sending Seq 2-2867: { Ans: , MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } 2014-03-20 13:30:10,712 DEBUG [cloud.api.ApiServlet] (catalina-exec-7:null) ===START=== 10.29.128.147 -- GET command=listVirtualMachines&id=4ec09c46-21b6-473b-acc3-3f4d92a805bd&response=json&sessionkey=diGqWRPhshb4jEtEnA3%2Fb61qoXI%3D&_=1395315008776 2014-03-20 13:30:10,796 DEBUG [cloud.api.ApiServlet] (catalina-exec-7:null) ===END=== 10.29.128.147 -- GET command=listVirtualMachines&id=4ec09c46-21b6-473b-acc3-3f4d92a805bd&response=json&sessionkey=diGqWRPhshb4jEtEnA3%2Fb61qoXI%3D&_=1395315008776 2014-03-20 13:30:10,928 DEBUG [cloud.api.ApiServlet] (catalina-exec-19:null) ===START=== 10.29.128.147 -- GET command=listOsTypes&response=json&sessionkey=diGqWRPhshb4jEtEnA3%2Fb61qoXI%3D&_=1395315008936 2014-03-20 13:30:11,011 DEBUG [cloud.api.ApiServlet] (catalina-exec-2:null) ===START=== 10.29.128.147 -- GET command=listTags&response=json&sessionkey=diGqWRPhshb4jEtEnA3%2Fb61qoXI%3D&resourceId=4ec09c46-21b6-473b-acc3-3f4d92a805bd&resourceType=UserVm&listAll=true&_=1395315008957 2014-03-20 13:30:11,041 DEBUG [cloud.api.ApiServlet] (catalina-exec-2:null) ===END=== 10.29.128.147 -- GET command=listTags&response=json&sessionkey=diGqWRPhshb4jEtEnA3%2Fb61qoXI%3D&resourceId=4ec09c46-21b6-473b-acc3-3f4d92a805bd&resourceType=UserVm&listAll=true&_=1395315008957 2014-03-20 13:30:11,453 DEBUG [cloud.api.ApiServlet] (catalina-exec-19:null) ===END=== 10.29.128.147 -- GET command=listOsTypes&response=json&sessionkey=diGqWRPhshb4jEtEnA3%2Fb61qoXI%3D&_=1395315008936 2014-03-20 13:30:13,453 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) StorageCollector is running... 2014-03-20 13:30:13,569 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 3-143851843: Received: { Ans: , MgmtId: 7063056740127, via: 3, Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2014-03-20 13:30:13,587 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-456:null) Seq 1-212795910: Executing request 2014-03-20 13:30:14,157 DEBUG [agent.transport.Request] (catalina-exec-12:null) Seq 1-212795911: Sending { Cmd , MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.GetVncPortCommand":{"id":3,"name":"i-3-3-VM","wait":0}}] } 2014-03-20 13:30:14,158 DEBUG [agent.transport.Request] (catalina-exec-12:null) Seq 1-212795911: Executing: { Cmd , MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.GetVncPortCommand":{"id":3,"name":"i-3-3-VM","wait":0}}] } 2014-03-20 13:30:14,159 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-98:null) Seq 1-212795911: Executing request 2014-03-20 13:30:14,399 WARN [xen.resource.CitrixResourceBase] (DirectAgent-98:null) There are no Consoles available to the vm : Template which allows VM installation from install media 2014-03-20 13:30:14,400 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-98:null) Seq 1-212795911: Response Received: 2014-03-20 13:30:14,401 DEBUG [agent.transport.Request] (DirectAgent-98:null) Seq 1-212795911: Processing: { Ans: , MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.GetVncPortAnswer":{"address":"consoleurl=null&sessionref=OpaqueRef:41c616c5-8e68-99ca-8af1-aaea30e33ba2","port":-1,"result":true,"wait":0}}] } 2014-03-20 13:30:14,402 DEBUG [agent.transport.Request] (catalina-exec-12:null) Seq 1-212795911: Received: { Ans: , MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 10, { GetVncPortAnswer } } 2014-03-20 13:30:14,403 DEBUG [cloud.servlet.ConsoleProxyServlet] (catalina-exec-12:null) Port info consoleurl=null&sessionref=OpaqueRef:41c616c5-8e68-99ca-8af1-aaea30e33ba2 2014-03-20 13:30:14,403 INFO [cloud.servlet.ConsoleProxyServlet] (catalina-exec-12:null) Parse host info returned from executing GetVNCPortCommand. host info: consoleurl=null&sessionref=OpaqueRef:41c616c5-8e68-99ca-8af1-aaea30e33ba2 2014-03-20 13:30:14,414 DEBUG [cloud.servlet.ConsoleProxyServlet] (catalina-exec-12:null) Compose console url: https://192-168-40-180.realhostip.com/ajax?token=ZNG4sxbBX9Kts8DPiptPk_nd30ScDHnAYoieeUUkW-5PHgJLWbMlVeO0K7sC1hRMmfL6U33CKc1Ph7y9q32IyN2pMy0J_-eRzJgW6uH3kFRQw3h9P-mKBplEOKVO8OnutOvoF7AZpfhKCmoB8evZbDPBCy8eEpOq5Xm7Av5bSkyckRn74X46WiTooUp-q1ChrOiUuWfRH58qCR4w5y_JYQ7vwVMUGauNkr_eex2QJ9iw1LaaLl1AT2odUt4bJg53 2014-03-20 13:30:14,414 DEBUG [cloud.servlet.ConsoleProxyServlet] (catalina-exec-12:null) the console url is :: <html><title>TestVM</title><frameset><frame src=" https://192-168-40-180.realhostip.com/ajax?token=ZNG4sxbBX9Kts8DPiptPk_nd30ScDHnAYoieeUUkW-5PHgJLWbMlVeO0K7sC1hRMmfL6U33CKc1Ph7y9q32IyN2pMy0J_-eRzJgW6uH3kFRQw3h9P-mKBplEOKVO8OnutOvoF7AZpfhKCmoB8evZbDPBCy8eEpOq5Xm7Av5bSkyckRn74X46WiTooUp-q1ChrOiUuWfRH58qCR4w5y_JYQ7vwVMUGauNkr_eex2QJ9iw1LaaLl1AT2odUt4bJg53 "></frame></frameset></html> 2014-03-20 13:30:14,450 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-456:null) Seq 1-212795910: Response Received: 2014-03-20 13:30:14,451 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-212795910: Received: { Ans: , MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2014-03-20 13:30:14,593 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 2-2868: Processing Seq 2-2868: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleAccessAuthenticationCommand":{"_host":"","_port":"-1","_vmId":"4ec09c46-21b6-473b-acc3-3f4d92a805bd","_sid":"e9eb6e0b9d6b16e6","_ticket":"MAQXocyTPSIWbPz72lNuOtUTLpw=","_isReauthenticating":false,"wait":0}}] } 2014-03-20 13:30:14,594 DEBUG [cloud.consoleproxy.AgentHookBase] (AgentManager-Handler-5:null) Console authentication. Ticket in url for :-1-4ec09c46-21b6-473b-acc3-3f4d92a805bd is MAQXocyTPSIWbPz72lNuOtUTLpw= 2014-03-20 13:30:14,594 DEBUG [cloud.consoleproxy.AgentHookBase] (AgentManager-Handler-5:null) Console authentication. Ticket in 1 minute boundary for :-1-4ec09c46-21b6-473b-acc3-3f4d92a805bd is uTR05n6GfIZpKO05m8tpJhVw1b8= 2014-03-20 13:30:14,595 DEBUG [cloud.consoleproxy.AgentHookBase] (AgentManager-Handler-5:null) Console authentication. Ticket in 2-minute boundary for :-1-4ec09c46-21b6-473b-acc3-3f4d92a805bd is wxipmtrsxXSxwIpMiquzb4cCzW0= 2014-03-20 13:30:14,595 ERROR [cloud.consoleproxy.AgentHookBase] (AgentManager-Handler-5:null) Access ticket expired or has been modified. vmId: 4ec09c46-21b6-473b-acc3-3f4d92a805bdticket in URL: MAQXocyTPSIWbPz72lNuOtUTLpw=, tickets to check against: uTR05n6GfIZpKO05m8tpJhVw1b8=,wxipmtrsxXSxwIpMiquzb4cCzW0= 2014-03-20 13:30:14,596 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 2-2868: Sending Seq 2-2868: { Ans: , MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.ConsoleAccessAuthenticationAnswer":{"_success":false,"_isReauthenticating":false,"_port":0,"result":true,"wait":0}}] } 2014-03-20 13:30:14,658 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 2-2869: Processing Seq 2-2869: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] } 2014-03-20 13:30:14,670 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 2-2869: Sending Seq 2-2869: { Ans: , MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } 2014-03-20 13:30:16,775 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-98:null) Ping from 1 2014-03-20 13:30:19,529 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-456:null) Seq 1-212795397: Executing request 2014-03-20 13:30:20,048 WARN [xen.resource.CitrixResourceBase] (DirectAgent-456:null) The VM is now missing marking it as Stopped i-3-3-VM 2014-03-20 13:30:20,049 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-456:null) Seq 1-212795397: Response Received: 2014-03-20 13:30:20,051 DEBUG [agent.transport.Request] (DirectAgent-456:null) Seq 1-212795397: Processing: { Ans: , MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.ClusterSyncAnswer":{"_clusterId":1,"_newStates":{"i-3-3-VM":{"t":"927ca03c-7756-4d71-8151-ca26e188a14c","u":"Stopped"}},"_isExecuted":false,"result":true,"wait":0}}] } 2014-03-20 13:30:20,066 DEBUG [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-456:null) VM i-3-3-VM: cs state = Running and realState = Stopped 2014-03-20 13:30:20,067 DEBUG [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-456:null) VM i-3-3-VM: cs state = Running and realState = Stopped 2014-03-20 13:30:20,067 DEBUG [cloud.ha.HighAvailabilityManagerImpl] (DirectAgent-456:null) VM does not require investigation so I'm marking it as Stopped: VM[User|TestVM] 2014-03-20 13:30:20,068 WARN [apache.cloudstack.alerts] (DirectAgent-456:null) alertType:: 8 // dataCenterId:: 1 // podId:: 1 // clusterId:: null // message:: VM (name: TestVM, id: 3) stopped unexpectedly on host id:1, availability zone id:1, pod id:1 2014-03-20 13:30:20,097 DEBUG [cloud.ha.HighAvailabilityManagerImpl] (DirectAgent-456:null) VM is not HA enabled so we're done. 2014-03-20 13:30:20,120 DEBUG [cloud.capacity.CapacityManagerImpl] (DirectAgent-456:null) VM state transitted from :Running to Stopping with event: StopRequestedvm's original host id: 1 new host id: 1 host id before state transition: 1 2014-03-20 13:30:20,134 DEBUG [agent.transport.Request] (DirectAgent-456:null) Seq 1-212795912: Sending { Cmd , MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-3-3-VM","wait":0}}] } 2014-03-20 13:30:20,135 DEBUG [agent.transport.Request] (DirectAgent-456:null) Seq 1-212795912: Executing: { Cmd , MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-3-3-VM","wait":0}}] } 2014-03-20 13:30:20,136 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-10:null) Seq 1-212795912: Executing request 2014-03-20 13:30:20,345 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-10:null) 9. The VM i-3-3-VM is in Stopping state 2014-03-20 13:30:20,507 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-10:null) 10. The VM i-3-3-VM is in Stopped state 2014-03-20 13:30:20,508 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-10:null) Seq 1-212795912: Response Received: 2014-03-20 13:30:20,509 DEBUG [agent.transport.Request] (DirectAgent-10:null) Seq 1-212795912: Processing: { Ans: , MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 110, [{"com.cloud.agent.api.StopAnswer":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:0","result":true,"details":"Stop VM i-3-3-VM Succeed","wait":0}}] } 2014-03-20 13:30:20,510 DEBUG [agent.transport.Request] (DirectAgent-456:null) Seq 1-212795912: Received: { Ans: , MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 110, { StopAnswer } } 2014-03-20 13:30:20,520 DEBUG [agent.manager.AgentAttache] (DirectAgent-10:null) Seq 1-212795912: No more commands found 2014-03-20 13:30:20,555 DEBUG [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-456:null) VM[User|TestVM] is stopped on the host. Proceeding to release resource held. 2014-03-20 13:30:20,582 DEBUG [cloud.network.NetworkManagerImpl] (DirectAgent-456:null) Changing active number of nics for network id=204 on -1 2014-03-20 13:30:20,605 DEBUG [cloud.network.NetworkManagerImpl] (DirectAgent-456:null) Asking VirtualRouter to release Nic[8-3-ccbb8759-31bd-46c3-bbf2-972896531ed1-192.168.40.182] 2014-03-20 13:30:20,614 DEBUG [cloud.network.NetworkManagerImpl] (DirectAgent-456:null) Asking SecurityGroupProvider to release Nic[8-3-ccbb8759-31bd-46c3-bbf2-972896531ed1-192.168.40.182] 2014-03-20 13:30:20,615 DEBUG [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-456:null) Successfully released network resources for the vm VM[User|TestVM] 2014-03-20 13:30:20,615 DEBUG [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-456:null) Successfully released storage resources for the vm VM[User|TestVM] 2014-03-20 13:30:20,771 DEBUG [cloud.capacity.CapacityManagerImpl] (DirectAgent-456:null) VM state transitted from :Stopping to Stopped with event: OperationSucceededvm's original host id: 1 new host id: null host id before state transition: 1 2014-03-20 13:30:20,799 DEBUG [cloud.capacity.CapacityManagerImpl] (DirectAgent-456:null) Hosts's actual total CPU: 160000 and CPU after applying overprovisioning: 160000 2014-03-20 13:30:20,800 DEBUG [cloud.capacity.CapacityManagerImpl] (DirectAgent-456:null) Hosts's actual total RAM: 540213924096 and RAM after applying overprovisioning: 540213936128 2014-03-20 13:30:20,800 DEBUG [cloud.capacity.CapacityManagerImpl] (DirectAgent-456:null) release cpu from host: 1, old used: 2000,reserved: 0, actual total: 160000, total with overprovisioning: 160000; new used: 1500,reserved:500; movedfromreserved: false,moveToReserveredtrue 2014-03-20 13:30:20,801 DEBUG [cloud.capacity.CapacityManagerImpl] (DirectAgent-456:null) release mem from host: 1, old used: 2013265920,reserved: 0, total: 540213936128; new used: 1476395008,reserved:536870912; movedfromreserved: false,moveToReserveredtrue 2014-03-20 13:30:20,864 INFO [cloud.ha.HighAvailabilityManagerImpl] (DirectAgent-456:null) Schedule vm for HA: VM[User|TestVM] 2014-03-20 13:30:20,884 INFO [cloud.ha.HighAvailabilityManagerImpl] (HA-Worker-0:work-5) Processing HAWork[5-HA-3-Stopped-Scheduled] 2014-03-20 13:30:20,892 DEBUG [agent.transport.Request] (DirectAgent-456:null) Seq 1-212795913: Sending { Cmd , MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-3-3-VM","wait":0}}] } 2014-03-20 13:30:20,893 DEBUG [agent.transport.Request] (DirectAgent-456:null) Seq 1-212795913: Executing: { Cmd , MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-3-3-VM","wait":0}}] } 2014-03-20 13:30:20,894 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-454:null) Seq 1-212795913: Executing request 2014-03-20 13:30:20,911 INFO [cloud.ha.HighAvailabilityManagerImpl] (HA-Worker-0:work-5) HA on VM[User|TestVM] 2014-03-20 13:30:20,926 DEBUG [cloud.ha.HighAvailabilityManagerImpl] (HA-Worker-0:work-5) VM is not HA enabled so we're done. 2014-03-20 13:30:20,927 INFO [cloud.ha.HighAvailabilityManagerImpl] (HA-Worker-0:work-5) Completed HAWork[5-HA-3-Stopped-Scheduled] 2014-03-20 13:30:21,003 INFO [xen.resource.CitrixResourceBase] (DirectAgent-454:null) VM does not exist on XenServer927ca03c-7756-4d71-8151-ca26e188a14c 2014-03-20 13:30:21,003 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-454:null) Seq 1-212795913: Response Received: 2014-03-20 13:30:21,004 DEBUG [agent.transport.Request] (DirectAgent-454:null) Seq 1-212795913: Processing: { Ans: , MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 110, [{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM does not exist","wait":0}}] } 2014-03-20 13:30:21,005 DEBUG [agent.manager.AgentAttache] (DirectAgent-454:null) Seq 1-212795913: No more commands found 2014-03-20 13:30:21,005 DEBUG [agent.transport.Request] (DirectAgent-456:null) Seq 1-212795913: Received: { Ans: , MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 110, { StopAnswer } } 2014-03-20 13:30:22,517 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) HostStatsCollector is running... 2014-03-20 13:30:22,546 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-158:null) Seq 1-212795914: Executing request 2014-03-20 13:30:22,989 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-158:null) Seq 1-212795914: Response Received: 2014-03-20 13:30:22,990 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-212795914: Received: { Ans: , MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } } 2014-03-20 13:30:24,600 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) VmStatsCollector is running... 2014-03-20 13:30:24,658 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 2-2870: Processing Seq 2-2870: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] } 2014-03-20 13:30:24,673 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 2-2870: Sending Seq 2-2870: { Ans: , MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } 2014-03-20 13:30:26,880 ERROR [cloud.alert.AlertManagerImpl] (Email-Alerts-Sender-6:null) Failed to send email alert javax.mail.MessagingException: Could not connect to SMTP host: outlook.afdb.org, port: 25 (java.net.ConnectException: Connection refused) 2014-03-20 13:30:31,482 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM 2014-03-20 13:30:32,096 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy 2014-03-20 13:30:34,634 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status. 2014-03-20 13:30:34,638 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status. 2014-03-20 13:30:34,661 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 2-2871: Processing Seq 2-2871: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] } 2014-03-20 13:30:34,676 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 2-2871: Sending Seq 2-2871: { Ans: , MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } 2014-03-20 13:30:39,660 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 2-2872: Processing Seq 2-2872: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] } 2014-03-20 13:30:39,674 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 2-2872: Sending Seq 2-2872: { Ans: , MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
