You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@cloudstack.apache.org by Osay Osman Yuuni <oy...@gmail.com> on 2014/03/20 12:45:05 UTC
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}}] }
Re: Issue with Instance
Posted by Osay Osman Yuuni <oy...@gmail.com>.
Thanks Suresh.
The output of the above command is "openvswitch".
It looks to be something to do with the template used for the
instantiation. When I instantiate using the default CentOS 5.6 template it
works. I've tried two other templates, one Windows 2012 R2 and the other
Ubuntu 12.04 LTS and both stay up and am able to log into the console.
However when I instantiate on a CentOS 6.3 template the resulting VM does
not stay up. The reason for the console error is because the VM shuts down
after a minute or so. I'm going to prepare new templates to try again.
Same issue with VMs instantiated on RedHat 6.3 template.
Thanks.
On 20 March 2014 14:04, Suresh Sadhu <Su...@citrix.com> wrote:
> 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:oyuuni@gmail.com]
> Sent: 20 March 2014 17:15
> To: users@cloudstack.apache.org
> 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}}] }
>
RE: Issue with Instance
Posted by Suresh Sadhu <Su...@citrix.com>.
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:oyuuni@gmail.com]
Sent: 20 March 2014 17:15
To: users@cloudstack.apache.org
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}}] }