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}}] }
