Return-Path: X-Original-To: apmail-cloudstack-users-archive@www.apache.org Delivered-To: apmail-cloudstack-users-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id B026418188 for ; Thu, 20 Aug 2015 15:49:48 +0000 (UTC) Received: (qmail 80560 invoked by uid 500); 20 Aug 2015 15:49:47 -0000 Delivered-To: apmail-cloudstack-users-archive@cloudstack.apache.org Received: (qmail 80505 invoked by uid 500); 20 Aug 2015 15:49:47 -0000 Mailing-List: contact users-help@cloudstack.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: users@cloudstack.apache.org Delivered-To: mailing list users@cloudstack.apache.org Received: (qmail 80494 invoked by uid 99); 20 Aug 2015 15:49:47 -0000 Received: from Unknown (HELO spamd4-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 20 Aug 2015 15:49:47 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd4-us-west.apache.org (ASF Mail Server at spamd4-us-west.apache.org) with ESMTP id C2055C0332 for ; Thu, 20 Aug 2015 15:49:46 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd4-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: 0.793 X-Spam-Level: X-Spam-Status: No, score=0.793 tagged_above=-999 required=6.31 tests=[KAM_ASCII_DIVIDERS=0.8, RP_MATCHES_RCVD=-0.006, SPF_HELO_PASS=-0.001, SPF_PASS=-0.001, URIBL_BLOCKED=0.001] autolearn=disabled Received: from mx1-eu-west.apache.org ([10.40.0.8]) by localhost (spamd4-us-west.apache.org [10.40.0.11]) (amavisd-new, port 10024) with ESMTP id RPKUFXRBDgVa for ; Thu, 20 Aug 2015 15:49:35 +0000 (UTC) Received: from SMTP.CITRIX.COM (smtp.citrix.com [66.165.176.89]) by mx1-eu-west.apache.org (ASF Mail Server at mx1-eu-west.apache.org) with ESMTPS id 5F2D520F4F for ; Thu, 20 Aug 2015 15:49:34 +0000 (UTC) X-IronPort-AV: E=Sophos;i="5.15,714,1432598400"; d="scan'208";a="292988191" From: Somesh Naidu To: "users@cloudstack.apache.org" Subject: RE: The agent doesn't reconnect if there are stopped VMs Thread-Topic: The agent doesn't reconnect if there are stopped VMs Thread-Index: AQHQ2yvQiZ8Oa2bEJ0C9lrC4wvCj154VGyeAgAAHfACAACHHAP//xHog Date: Thu, 20 Aug 2015 15:49:25 +0000 Message-ID: References: <20150820093640.GA6547@shagomer.uplink.tucha13.net> ,<20150820132020.GB6547@shagomer.uplink.tucha13.net> In-Reply-To: Accept-Language: en-US Content-Language: en-US X-MS-Has-Attach: X-MS-TNEF-Correlator: Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: quoted-printable MIME-Version: 1.0 X-DLP: MIA2 > 2015-08-18 06:24:46,542 DEBUG [c.c.c.CapacityManagerImpl] (AgentConnectTa= skPool-213:ctx-76903ef6) Found 1 VM, not running on host 27 > 2015-08-18 06:24:46,544 ERROR [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Monitor ComputeCapacityListener says there is an er= ror in the connect process for 27 due to null > java.lang.NullPointerException It will help if you send the complete exception stack for the above NPE. Regards, Somesh -----Original Message----- From: Simon Weller [mailto:sweller@ena.com]=20 Sent: Thursday, August 20, 2015 11:21 AM To: users@cloudstack.apache.org Subject: Re: The agent doesn't reconnect if there are stopped VMs Do you have any dynamic service offerings? ________________________________________ From: Vladimir Melnik Sent: Thursday, August 20, 2015 8:20 AM To: users@cloudstack.apache.org Subject: Re: The agent doesn't reconnect if there are stopped VMs Oh, I'm sorry, I should have initially send the DEBUG-log! Here is an example: --- 8< --- 2015-07-29 00:53:42,988 INFO [utils.nio.NioClient] (Agent-Selector:null) C= onnecting to ***.***.***.***:8250 2015-07-29 00:53:44,254 INFO [utils.nio.NioClient] (Agent-Selector:null) S= SL: Handshake done 2015-07-29 00:53:44,255 INFO [utils.nio.NioClient] (Agent-Selector:null) C= onnected to ***.***.***.***:8250 2015-07-29 00:53:44,258 WARN [kvm.resource.LibvirtComputingResource] (Agen= t-Handler-1:null) Could not read cpuinfo_max_freq 2015-07-29 00:53:44,266 DEBUG [kvm.resource.LibvirtCapXMLParser] (Agent-Han= dler-1:null) Found /usr/libexec/qemu-kvm as a suiteable emulat or 2015-07-29 00:53:44,266 DEBUG [kvm.resource.LibvirtComputingResource] (Agen= t-Handler-1:null) Executing: /bin/bash -c qemu-img --help|grep convert 2015-07-29 00:53:44,270 DEBUG [kvm.resource.LibvirtComputingResource] (Agen= t-Handler-1:null) Execution is successful. 2015-07-29 00:53:44,271 DEBUG [kvm.resource.LibvirtComputingResource] (Agen= t-Handler-1:null) convert [-c] [-p] [-f fmt] [-t cache] [-T src_cache] [-O output_fmt] [-o options] [-S sparse_size] filename [filename= 2 [...]] output_filename 2015-07-29 00:53:44,271 DEBUG [kvm.resource.LibvirtComputingResource] (Agen= t-Handler-1:null) cpus=3D8, speed=3D2660, ram=3D30153224192, dom0ram =3D805306368, cpu sockets=3D1 2015-07-29 00:53:44,272 DEBUG [cloud.resource.ServerResourceBase] (Agent-Ha= ndler-1:null) Parameters for private nic: 172.26.65.1 - 84:2b: 2b:56:d3:d9-255.255.255.0 2015-07-29 00:53:44,272 DEBUG [cloud.resource.ServerResourceBase] (Agent-Ha= ndler-1:null) Parameters for storage nic: 172.26.65.1 - 84:2b: 2b:56:d3:d9-255.255.255.0 2015-07-29 00:53:44,272 DEBUG [cloud.resource.ServerResourceBase] (Agent-Ha= ndler-1:null) Parameters for pubic nic: 172.26.65.1 - 84:2b:2b :56:d3:d9-255.255.255.0 2015-07-29 00:53:44,272 DEBUG [kvm.resource.LibvirtComputingResource] (Agen= t-Handler-1:null) Executing: /usr/share/cloudstack-common/scri pts/vm/hypervisor/versions.sh 2015-07-29 00:53:44,281 DEBUG [kvm.resource.LibvirtComputingResource] (Agen= t-Handler-1:null) Execution is successful. 2015-07-29 00:53:44,282 DEBUG [kvm.resource.LibvirtComputingResource] (Agen= t-Handler-1:null) Executing: sudo grep InitiatorName=3D /etc/isc si/initiatorname.iscsi 2015-07-29 00:53:44,290 DEBUG [kvm.resource.LibvirtComputingResource] (Agen= t-Handler-1:null) Execution is successful. 2015-07-29 00:53:44,290 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Ha= ndler-1:null) Attempting to create storage pool 42bed7d9-88ae- 403d-9b53-0b44f31b2312 (Filesystem) in libvirt 2015-07-29 00:53:44,292 DEBUG [kvm.storage.LibvirtStorageAdaptor] (Agent-Ha= ndler-1:null) Found existing defined storage pool 42bed7d9-88a e-403d-9b53-0b44f31b2312, using it. 2015-07-29 00:53:44,292 DEBUG [kvm.storage.LibvirtStorageAdaptor] (Agent-Ha= ndler-1:null) Trying to fetch storage pool 42bed7d9-88ae-403d-9b53-0b44f31b= 2312 from libvirt 2015-07-29 00:53:44,811 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null) Ex= ecuting: hostname 2015-07-29 00:53:44,813 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null) Ex= ecution is successful. 2015-07-29 00:53:44,834 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null) Ex= ecuting: hostname 2015-07-29 00:53:44,836 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null) Ex= ecution is successful. 2015-07-29 00:53:44,838 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null) Se= nding Startup: Seq 0-64: { Cmd , MgmtId: -1, via: 0, Ver: v1, Flags: 1, [{= "com.cloud.agent.api.StartupRoutingCommand":{"cpuSockets":1,"cpus":8,"speed= ":2660,"memory":30153224192,"dom0MinMemory":805306368,"poolSync":false,"cap= s":"hvm,snapshot","pool":"/root","hypervisorType":"KVM","hostDetails":{"com= .cloud.network.Networks.RouterPrivateIpStrategy":"HostLocal","Host.OS":"Cen= tOS","Host.OS.Kernel.Version":"2.6.32-504.16.2.el6.x86_64","Host.OS.Version= ":"6.6"},"hostTags":[],"groupDetails":{},"type":"Routing","dataCenter":"4",= "pod":"5","cluster":"5","guid":"26e2bf7d-2fcf-3a67-a23d-ce9c09ef2ca5-Libvir= tComputingResource","name":"***.***.***","id":0,"version":"4.5.1","iqn":"iq= n.1994-05.com.redhat:f044a5e741a1","publicIpAddress":"172.26.65.1","publicN= etmask":"255.255.255.0","publicMacAddress":"84:2b:2b:56:d3:d9","privateIpAd= dress":"172.26.65.1","privateMacAddress":"84:2b:2b:56:d3:d9","privateNetmas= k":"255.255.255.0","storageIpAddress":"172.26.65.1","storageNetmask":"255.2= 55.255.0","storageMacAddress":"84:2b:2b:56:d3:d9","resourceName":"LibvirtCo= mputingResource","gatewayIpAddress":"103.247.149.1","wait":0}},{"com.cloud.= agent.api.StartupStorageCommand":{"totalSize":0,"poolInfo":{"uuid":"42bed7d= 9-88ae-403d-9b53-0b44f31b2312","host":"172.26.65.1","localPath":"/var/lib/l= ibvirt/images","hostPath":"/var/lib/libvirt/images","poolType":"Filesystem"= ,"capacityBytes":913829568512,"availableBytes":810211274752},"resourceType"= :"STORAGE_POOL","hostDetails":{},"type":"Storage","dataCenter":"4","pod":"5= ","guid":"26e2bf7d-2fcf-3a67-a23d-ce9c09ef2ca5-LibvirtComputingResource","n= ame":"***.***.***","id":0,"version":"4.5.1","resourceName":"LibvirtComputin= gResource","wait":0}}] } 2015-07-29 00:53:44,838 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null) St= artup task created 2015-07-29 00:53:45,552 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null) Re= ceived response: Seq 0-64: { Ans: , MgmtId: 279278805451086, via: -1, Ver:= v1, Flags: 100000, [{"com.cloud.agent.api.StartupAnswer":{"hostId":0,"ping= Interval":60,"result":true,"wait":0}}] } 2015-07-29 00:53:45,553 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null) St= artup task cancelled 2015-07-29 00:53:45,553 INFO [cloud.agent.Agent] (Agent-Handler-2:null) Pr= occess agent startup answer, agent id =3D 0 2015-07-29 00:53:45,553 INFO [cloud.agent.Agent] (Agent-Handler-2:null) Se= t agent id 0 2015-07-29 00:53:45,553 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:n= ull) Request:Seq 22-7511722703477276673: { Cmd , MgmtId: 279278805451086, = via: 22, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.CheckNetworkCommand= ":{"networkInfoList":[{"physicalNetworkId":203}],"wait":0}}] } 2015-07-29 00:53:45,553 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:n= ull) Processing command: com.cloud.agent.api.CheckNetworkCommand 2015-07-29 00:53:45,553 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null) Ad= ding a watch list 2015-07-29 00:53:45,553 INFO [cloud.agent.Agent] (Agent-Handler-2:null) St= artup Response Received: agent id =3D 0 2015-07-29 00:53:45,554 DEBUG [kvm.resource.LibvirtComputingResource] (Ugen= tTask-5:null) Executing: /usr/share/cloudstack-common/scripts/vm/network/se= curity_group.py get_rule_logs_for_vms 2015-07-29 00:53:45,554 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:n= ull) Seq 22-7511722703477276673: { Ans: , MgmtId: 279278805451086, via: 22= , Ver: v1, Flags: 110, [{"com.cloud.agent.api.CheckNetworkAnswer":{"_reconn= ect":false,"result":true,"wait":0}}] } 2015-07-29 00:53:45,635 DEBUG [kvm.resource.LibvirtComputingResource] (Ugen= tTask-5:null) Execution is successful. 2015-07-29 00:53:45,638 DEBUG [cloud.agent.Agent] (UgentTask-5:null) Sendin= g ping: Seq 0-65: { Cmd , MgmtId: -1, via: 0, Ver: v1, Flags: 11, [{"com.c= loud.agent.api.PingRoutingWithNwGroupsCommand":{"newGroupStates":{},"_hostV= mStateReport":{},"_gatewayAccessible":true,"_vnetAccessible":true,"hostType= ":"Routing","hostId":0,"wait":0}}] } 2015-07-29 00:53:46,084 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:n= ull) Request:Seq 22-7511722703477276674: { Cmd , MgmtId: 279278805451086, = via: 22, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.CleanupNetworkRules= Cmd":{"interval":2299,"wait":0}}] } 2015-07-29 00:53:46,084 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:n= ull) Processing command: com.cloud.agent.api.CleanupNetworkRulesCmd 2015-07-29 00:53:46,084 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:n= ull) Adding a watch list 2015-07-29 00:53:46,084 DEBUG [kvm.resource.LibvirtComputingResource] (Agen= t-Handler-1:null) Executing: /usr/share/cloudstack-common/scripts/vm/networ= k/security_group.py cleanup_rules 2015-07-29 00:53:46,084 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:n= ull) Seq 22-7511722703477276674: { Ans: , MgmtId: 279278805451086, via: 22= , Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":= 0}}] } 2015-07-29 00:53:46,084 DEBUG [cloud.agent.Agent] (Agent-Handler-5:null) Re= ceived response: Seq 0-65: { Ans: , MgmtId: 279278805451086, via: 22, Ver:= v1, Flags: 100010, [{"com.cloud.agent.api.PingAnswer":{"_command":{"hostTy= pe":"Routing","hostId":0,"wait":0},"result":true,"wait":0}}] } 2015-07-29 00:53:46,159 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:n= ull) Request:Seq 22-7511722703477276675: { Cmd , MgmtId: 279278805451086, = via: 22, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.ModifySshKeysComman= d":{"wait":0}}] } 2015-07-29 00:53:46,160 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:n= ull) Processing command: com.cloud.agent.api.ModifySshKeysCommand 2015-07-29 00:53:46,160 DEBUG [kvm.resource.LibvirtComputingResource] (agen= tRequest-Handler-1:null) Executing: chmod 600 /root/.ssh/id_rsa.cloud 2015-07-29 00:53:46,161 DEBUG [kvm.resource.LibvirtComputingResource] (agen= tRequest-Handler-1:null) Execution is successful. 2015-07-29 00:53:46,162 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:n= ull) Seq 22-7511722703477276675: { Ans: , MgmtId: 279278805451086, via: 22= , Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":= 0}}] } 2015-07-29 00:53:46,177 DEBUG [kvm.resource.LibvirtComputingResource] (Agen= t-Handler-1:null) Execution is successful. 2015-07-29 00:53:46,178 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null) Wa= tch Sent: Seq 22-7511722703477276674: { Ans: , MgmtId: 279278805451086, vi= a: 22, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"d= etails":"","wait":0}}] } 2015-07-29 00:53:46,195 DEBUG [utils.nio.NioConnection] (Agent-Selector:nul= l) Location 1: Socket Socket[addr=3D/***.***.***.***,port=3D8250,localport= =3D59991] closed on read. Probably -1 returned: Connection closed with -1 = on reading size. 2015-07-29 00:53:46,196 DEBUG [utils.nio.NioConnection] (Agent-Selector:nul= l) Closing socket Socket[addr=3D/***.***.***.***,port=3D8250,localport=3D59= 991] 2015-07-29 00:53:46,196 DEBUG [cloud.agent.Agent] (Agent-Handler-4:null) Cl= earing watch list: 2 2015-07-29 00:53:46,196 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:n= ull) Request:Seq 22-7511722703477276676: { Cmd , MgmtId: 279278805451086, = via: 22, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.ModifySshKeysComman= d":{"wait":0}}] } 2015-07-29 00:53:46,196 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:n= ull) Processing command: com.cloud.agent.api.ModifySshKeysCommand 2015-07-29 00:53:46,197 DEBUG [kvm.resource.LibvirtComputingResource] (agen= tRequest-Handler-2:null) Executing: chmod 600 /root/.ssh/id_rsa.cloud 2015-07-29 00:53:46,198 DEBUG [kvm.resource.LibvirtComputingResource] (agen= tRequest-Handler-2:null) Execution is successful. 2015-07-29 00:53:46,199 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:n= ull) Seq 22-7511722703477276676: { Ans: , MgmtId: 279278805451086, via: 22= , Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":= 0}}] } 2015-07-29 00:53:46,199 WARN [cloud.agent.Agent] (agentRequest-Handler-2:n= ull) Unable to send response: Seq 22-7511722703477276676: { Ans: , MgmtId:= 279278805451086, via: 22, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answe= r":{"result":true,"wait":0}}] } 2015-07-29 00:53:49,255 INFO [cloud.agent.Agent] (Agent-Handler-4:null) Co= nnected to the server 2015-07-29 00:53:51,196 INFO [cloud.agent.Agent] (Agent-Handler-4:null) Lo= st connection to the server. Dealing with the remaining commands... 2015-07-29 00:53:56,198 INFO [utils.nio.NioClient] (Agent-Handler-4:null) = NioClient connection closed --- >8 --- It seems that the connection is being closed by the management-server, but I don't see why. On Thu, Aug 20, 2015 at 12:53:33PM +0000, Simon Weller wrote: > Vladimir, > > Could you turn up debugging on the agent and post another agent log? > > You can do this by running: sed -i 's/INFO/DEBUG/g' /etc/cloudstack/agent= /log4j-cloud.xml > Then restart the agent. > > - Si > ________________________________________ > From: Vladimir Melnik > Sent: Thursday, August 20, 2015 4:36 AM > To: users@cloudstack.apache.org > Subject: The agent doesn't reconnect if there are stopped VMs > > Dear colleagues, > > I have a simple setup where the management server (CentOS-6.6 + > ACS-4.5.1) is orchestrating a bunch of KVM hosts (each of them is > running CentOS-6.6 + ACS-4.5.1 as well). > > Any host with at least one VM in the "Stopped" state can't reconnect to > the management server. It has the "Alert" state and here's what I see in > the management server's log-file: > > --- 8< --- > 2015-08-18 06:24:46,332 DEBUG [c.c.a.t.Request] (AgentConnectTaskPool-213= :ctx-76903ef6) Seq 0-148: Processing the first command { Cmd , > MgmtId: -1, via: 0, Ver: v1, Flags: 1, [{"com.cloud.agent.api.StartupRout= ingCommand":{"cpuSockets":1,"cpus":48,"speed":2299,"memory":6743 > 9632384,"dom0MinMemory":805306368,"poolSync":false,"caps":"hvm,snapshot",= "pool":"/root","hypervisorType":"KVM","hostDetails":{"com.cloud. > network.Networks.RouterPrivateIpStrategy":"HostLocal","Host.OS":"CentOS",= "Host.OS.Kernel.Version":"2.6.32-504.23.4.el6.x86_64","Host.OS.V > ersion":"6.6"},"hostTags":[],"groupDetails":{},"type":"Routing","dataCent= er":"6","pod":"7","cluster":"7","guid":"1318c38d-4ed6-3296-a6bd-753676e25ad= 4-LibvirtComputingResource","name":"***.***.***","id":0,"version":"4.5.1","= publicIpAddress":"172.27.65.1","publicNetmask":"255.255.255.0","publicMacAd= dress":"ec:f4:bb:d6:89:c5","privateIpAddress":"172.27.65.1","privateMacAddr= ess":"ec:f4:bb:d6:89:c5","privateNetmask":"255.255.255.0","storageIpAddress= ":"172.27.65.1","storageNetmask":"255.255.255.0","storageMacAddress":"ec:f4= :bb:d6:89:c5","resourceName":"LibvirtComputingResource","gatewayIpAddress":= "***.***.***.***","wait":0}},{"com.cloud.agent.api.StartupStorageCommand":{= "totalSize":0,"poolInfo":{"uuid":"51670fbd-ece2-4a3e-9971-3928e6576f0e","ho= st":"172.27.65.1","localPath":"/var/lib/libvirt/images","hostPath":"/var/li= b/libvirt/images","poolType":"Filesystem","capacityBytes":1563804868608,"av= ailableBytes":1474368700416},"resourceType":"STORAGE_POOL","hostDetails":{}= ,"type":"Storage","dataCenter":"6","pod":"7","guid":"1318c38d-4ed6-3296-a6b= d-753676e25ad4-LibvirtComputingResource","name":"***.***.***","id":0,"versi= on":"4.5.1","resourceName":"LibvirtComputingResource","wait":0}}] } > 2015-08-18 06:24:46,336 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTa= skPool-213:ctx-76903ef6) Dispatching resource state event CREATE_HOST_VO_FO= R_CONNECTED to BaremetalDhcpManagerImpl > 2015-08-18 06:24:46,336 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTa= skPool-213:ctx-76903ef6) Dispatching resource state event CREATE_HOST_VO_FO= R_CONNECTED to BaremetalPxeManagerImpl > 2015-08-18 06:24:46,336 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTa= skPool-213:ctx-76903ef6) Dispatching resource state event CREATE_HOST_VO_FO= R_CONNECTED to NetworkUsageManagerImpl > 2015-08-18 06:24:46,336 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTa= skPool-213:ctx-76903ef6) Dispatching resource state event CREATE_HOST_VO_FO= R_CONNECTED to NuageVspElement > 2015-08-18 06:24:46,336 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTa= skPool-213:ctx-76903ef6) Dispatching resource state event CREATE_HOST_VO_FO= R_CONNECTED to Ovs > 2015-08-18 06:24:46,336 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTa= skPool-213:ctx-76903ef6) Dispatching resource state event CREATE_HOST_VO_FO= R_CONNECTED to PaloAltoExternalFirewallElement > 2015-08-18 06:24:46,336 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTa= skPool-213:ctx-76903ef6) Dispatching resource state event CREATE_HOST_VO_FO= R_CONNECTED to GloboDnsElement > 2015-08-18 06:24:46,336 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTa= skPool-213:ctx-76903ef6) Dispatching resource state event CREATE_HOST_VO_FO= R_CONNECTED to KvmServerDiscoverer > 2015-08-18 06:24:46,362 DEBUG [c.c.r.ResourceState] (AgentConnectTaskPool= -213:ctx-76903ef6) Resource state update: [id =3D 27; name =3D ***.***.***;= old state =3D Enabled; event =3D InternalCreated; new state =3D Enabled] > 2015-08-18 06:24:46,362 DEBUG [c.c.h.Status] (AgentConnectTaskPool-213:ct= x-76903ef6) Transition:[Resource state =3D Enabled, Agent event =3D AgentCo= nnected, Host id =3D 27, name =3D ***.***.***] > 2015-08-18 06:24:46,365 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (AgentC= onnectTaskPool-213:ctx-76903ef6) create ClusteredAgentAttache for 27 > 2015-08-18 06:24:46,367 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Connect to listener: XcpServerDiscoverer > 2015-08-18 06:24:46,367 DEBUG [c.c.h.x.d.XcpServerDiscoverer] (AgentConne= ctTaskPool-213:ctx-76903ef6) Not XenServer so moving on. > 2015-08-18 06:24:46,367 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Connect to listener: HypervServerDiscoverer > 2015-08-18 06:24:46,367 DEBUG [c.c.h.h.d.HypervServerDiscoverer] (AgentCo= nnectTaskPool-213:ctx-76903ef6) Not Hyper-V hypervisor, so moving on. > 2015-08-18 06:24:46,367 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Connect to listener: ClusteredVirtualMachin= eManagerImpl > 2015-08-18 06:24:46,367 DEBUG [c.c.v.VirtualMachineManagerImpl] (AgentCon= nectTaskPool-213:ctx-76903ef6) Received startup command from hypervisor hos= t. host id: 27 > 2015-08-18 06:24:46,367 INFO [c.c.v.VirtualMachinePowerStateSyncImpl] (A= gentConnectTaskPool-213:ctx-76903ef6) Reset VM power state sync for host: 2= 7 > 2015-08-18 06:24:46,369 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Connect to listener: NetworkOrchestrator > 2015-08-18 06:24:46,371 DEBUG [o.a.c.e.o.NetworkOrchestrator] (AgentConne= ctTaskPool-213:ctx-76903ef6) Host's hypervisorType is: KVM > 2015-08-18 06:24:46,376 DEBUG [o.a.c.e.o.NetworkOrchestrator] (AgentConne= ctTaskPool-213:ctx-76903ef6) Sending CheckNetworkCommand to check the Netwo= rk is setup correctly on Agent > 2015-08-18 06:24:46,379 DEBUG [c.c.a.t.Request] (AgentConnectTaskPool-213= :ctx-76903ef6) Seq 27-1186417026835415041: Sending { Cmd , MgmtId: 2792788= 05451086, via: 27(***.***.***), Ver: v1, Flags: 100111, [{"com.cloud.agent.= api.CheckNetworkCommand":{"networkInfoList":[{"physicalNetworkId":205}],"wa= it":0}}] } > 2015-08-18 06:24:46,421 DEBUG [c.c.a.t.Request] (AgentManager-Handler-15:= null) Seq 27-1186417026835415041: Processing: { Ans: , MgmtId: 27927880545= 1086, via: 27, Ver: v1, Flags: 110, [{"com.cloud.agent.api.CheckNetworkAnsw= er":{"_reconnect":false,"result":true,"wait":0}}] } > 2015-08-18 06:24:46,422 DEBUG [c.c.a.t.Request] (AgentConnectTaskPool-213= :ctx-76903ef6) Seq 27-1186417026835415041: Received: { Ans: , MgmtId: 2792= 78805451086, via: 27, Ver: v1, Flags: 110, { CheckNetworkAnswer } } > 2015-08-18 06:24:46,422 DEBUG [c.c.a.m.AgentAttache] (AgentManager-Handle= r-15:null) Seq 27-1186417026835415041: No more commands found > 2015-08-18 06:24:46,422 DEBUG [o.a.c.e.o.NetworkOrchestrator] (AgentConne= ctTaskPool-213:ctx-76903ef6) Network setup is correct on Agent > 2015-08-18 06:24:46,422 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Connect to listener: SecurityGroupListener > 2015-08-18 06:24:46,422 INFO [c.c.n.s.SecurityGroupListener] (AgentConne= ctTaskPool-213:ctx-76903ef6) Received a host startup notification > 2015-08-18 06:24:46,424 DEBUG [c.c.a.t.Request] (AgentConnectTaskPool-213= :ctx-76903ef6) Seq 27-1186417026835415042: Sending { Cmd , MgmtId: 2792788= 05451086, via: 27(***.***.***), Ver: v1, Flags: 100011, [{"com.cloud.agent.= api.CleanupNetworkRulesCmd":{"interval":2417,"wait":0}}] } > 2015-08-18 06:24:46,424 INFO [c.c.n.s.SecurityGroupListener] (AgentConne= ctTaskPool-213:ctx-76903ef6) Scheduled network rules cleanup, interval=3D24= 17 > 2015-08-18 06:24:46,424 INFO [c.c.n.s.SecurityGroupListener] (AgentConne= ctTaskPool-213:ctx-76903ef6) Received a host startup notification > 2015-08-18 06:24:46,424 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Connect to listener: StoragePoolMonitor > 2015-08-18 06:24:46,428 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Connect to listener: DeploymentPlanningMana= gerImpl > 2015-08-18 06:24:46,429 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Connect to listener: VmwareManagerImpl > 2015-08-18 06:24:46,429 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Connect to listener: SecondaryStorageListen= er > 2015-08-18 06:24:46,429 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Connect to listener: SshKeysDistriMonitor > 2015-08-18 06:24:46,433 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha= ndler-13:null) Ping from 27 > 2015-08-18 06:24:46,433 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (A= gentManager-Handler-13:null) Process host VM state report from ping process= . host: 27 > 2015-08-18 06:24:46,434 DEBUG [c.c.a.t.Request] (AgentConnectTaskPool-213= :ctx-76903ef6) Seq 27-1186417026835415043: Sending { Cmd , MgmtId: 2792788= 05451086, via: 27(***.***.***), Ver: v1, Flags: 100011, [{"com.cloud.agent.= api.ModifySshKeysCommand":{"wait":0}}] } > 2015-08-18 06:24:46,435 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Connect to listener: VpcVirtualNetworkAppli= anceManagerImpl > 2015-08-18 06:24:46,436 DEBUG [c.c.a.t.Request] (AgentManager-Handler-6:n= ull) Seq 27-1186417026835415042: Processing: { Ans: , MgmtId: 279278805451= 086, via: 27, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":= true,"wait":0}}] } > 2015-08-18 06:24:46,438 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Connect to listener: BehindOnPingListener > 2015-08-18 06:24:46,438 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Connect to listener: DownloadListener > 2015-08-18 06:24:46,447 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (A= gentManager-Handler-13:null) Process VM state report. host: 27, number of r= ecords in report: 5 > 2015-08-18 06:24:46,447 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (A= gentManager-Handler-13:null) VM state report. host: 27, vm id: 1032, power = state: PowerOn > 2015-08-18 06:24:46,451 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (A= gentManager-Handler-13:null) VM state report is updated. host: 27, vm id: 1= 032, power state: PowerOn > 2015-08-18 06:24:46,457 DEBUG [c.c.c.CapacityManagerImpl] (AgentManager-H= andler-13:null) VM state transitted from :Running to Running with event: Fo= llowAgentPowerOnReportvm's original host id: 27 new host id: 27 host id bef= ore state transition: 27 > 2015-08-18 06:24:46,458 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (A= gentManager-Handler-13:null) VM state report. host: 27, vm id: 1033, power = state: PowerOn > 2015-08-18 06:24:46,469 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (A= gentManager-Handler-13:null) VM state report is updated. host: 27, vm id: 1= 033, power state: PowerOn > 2015-08-18 06:24:46,474 DEBUG [c.c.c.CapacityManagerImpl] (AgentManager-H= andler-13:null) VM state transitted from :Running to Running with event: Fo= llowAgentPowerOnReportvm's original host id: 27 new host id: 27 host id bef= ore state transition: 27 > 2015-08-18 06:24:46,475 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (A= gentManager-Handler-13:null) VM state report. host: 27, vm id: 1038, power = state: PowerOn > 2015-08-18 06:24:46,478 DEBUG [c.c.a.t.Request] (AgentManager-Handler-10:= null) Seq 27-1186417026835415043: Processing: { Ans: , MgmtId: 27927880545= 1086, via: 27, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result"= :true,"wait":0}}] } > 2015-08-18 06:24:46,479 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (A= gentManager-Handler-13:null) VM state report is updated. host: 27, vm id: 1= 038, power state: PowerOn > 2015-08-18 06:24:46,484 DEBUG [c.c.c.CapacityManagerImpl] (AgentManager-H= andler-13:null) VM state transitted from :Running to Running with event: Fo= llowAgentPowerOnReportvm's original host id: 27 new host id: 27 host id bef= ore state transition: 27 > 2015-08-18 06:24:46,485 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (A= gentManager-Handler-13:null) VM state report. host: 27, vm id: 1029, power = state: PowerOn > 2015-08-18 06:24:46,488 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (A= gentManager-Handler-13:null) VM state report is updated. host: 27, vm id: 1= 029, power state: PowerOn > 2015-08-18 06:24:46,493 DEBUG [c.c.c.CapacityManagerImpl] (AgentManager-H= andler-13:null) VM state transitted from :Running to Running with event: Fo= llowAgentPowerOnReportvm's original host id: 27 new host id: 27 host id bef= ore state transition: 27 > 2015-08-18 06:24:46,494 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (A= gentManager-Handler-13:null) VM state report. host: 27, vm id: 1030, power = state: PowerOn > 2015-08-18 06:24:46,497 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (A= gentManager-Handler-13:null) VM state report is updated. host: 27, vm id: 1= 030, power state: PowerOn > 2015-08-18 06:24:46,502 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Connect to listener: SshKeysDistriMonitor > 2015-08-18 06:24:46,502 DEBUG [c.c.c.CapacityManagerImpl] (AgentManager-H= andler-13:null) VM state transitted from :Running to Running with event: Fo= llowAgentPowerOnReportvm's original host id: 27 new host id: 27 host id bef= ore state transition: 27 > 2015-08-18 06:24:46,507 DEBUG [c.c.a.t.Request] (AgentConnectTaskPool-213= :ctx-76903ef6) Seq 27-1186417026835415044: Sending { Cmd , MgmtId: 2792788= 05451086, via: 27(***.***.***), Ver: v1, Flags: 100011, [{"com.cloud.agent.= api.ModifySshKeysCommand":{"wait":0}}] } > 2015-08-18 06:24:46,507 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Connect to listener: VirtualNetworkApplianc= eManagerImpl > 2015-08-18 06:24:46,509 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Connect to listener: DirectNetworkStatsList= ener > 2015-08-18 06:24:46,509 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Connect to listener: UploadListener > 2015-08-18 06:24:46,509 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Connect to listener: ConsoleProxyListener > 2015-08-18 06:24:46,509 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Connect to listener: LocalStoragePoolListen= er > 2015-08-18 06:24:46,510 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (A= gentManager-Handler-13:null) Done with process of VM state report. host: 27 > 2015-08-18 06:24:46,515 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha= ndler-13:null) Not processing PingRoutingCommand for agent id=3D0; can't fi= nd the host in the DB > 2015-08-18 06:24:46,516 DEBUG [c.c.a.t.Request] (AgentManager-Handler-3:n= ull) Seq 27-1186417026835415044: Processing: { Ans: , MgmtId: 279278805451= 086, via: 27, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":= true,"wait":0}}] } > 2015-08-18 06:24:46,519 DEBUG [c.c.s.StorageManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Found storage pool ***.***.*** Local Storage of typ= e Filesystem > 2015-08-18 06:24:46,519 DEBUG [c.c.s.StorageManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Total over provisioned capacity of the pool ***.***= .*** Local Storage id: 16 is 1563804868608 > 2015-08-18 06:24:46,522 DEBUG [c.c.s.StorageManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Successfully set Capacity - 1563804868608 for capac= ity type - 9 , DataCenterId - 6, HostOrPoolId - 16, PodId 7 > 2015-08-18 06:24:46,524 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Connect to listener: StorageCapacityListene= r > 2015-08-18 06:24:46,524 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Connect to listener: ComputeCapacityListene= r > 2015-08-18 06:24:46,532 DEBUG [c.c.c.CapacityManagerImpl] (AgentConnectTa= skPool-213:ctx-76903ef6) Found 5 VMs on host 27 > 2015-08-18 06:24:46,542 DEBUG [c.c.c.CapacityManagerImpl] (AgentConnectTa= skPool-213:ctx-76903ef6) Found 1 VM, not running on host 27 > 2015-08-18 06:24:46,544 ERROR [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Monitor ComputeCapacityListener says there is an er= ror in the connect process for 27 due to null > java.lang.NullPointerException > 2015-08-18 06:24:46,544 INFO [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Host 27 is disconnecting with event AgentDisconnect= ed > 2015-08-18 06:24:46,545 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) The next status of agent 27is Alert, current status= is Connecting > 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Deregistering link for 27 with state Alert > 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Remove Agent : 27 > 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.ConnectedAgentAttache] (AgentConne= ctTaskPool-213:ctx-76903ef6) Processing Disconnect. > 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentAttache] (AgentConnectTaskPoo= l-213:ctx-76903ef6) Seq 27-1186417026835415042: Sending disconnect to class= com.cloud.network.security.SecurityGroupListener > 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Disconnect to listener: com.cloud.hyperviso= r.xenserver.discoverer.XcpServerDiscoverer > 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Disconnect to listener: com.cloud.hyperviso= r.hyperv.discoverer.HypervServerDiscoverer > 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Disconnect to listener: com.cloud.vm.Cluste= redVirtualMachineManagerImpl > 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Disconnect to listener: org.apache.cloudsta= ck.engine.orchestration.NetworkOrchestrator > 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Disconnect to listener: com.cloud.network.s= ecurity.SecurityGroupListener > 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Disconnect to listener: com.cloud.storage.l= istener.StoragePoolMonitor > 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Disconnect to listener: com.cloud.deploy.De= ploymentPlanningManagerImpl > 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Disconnect to listener: com.cloud.hyperviso= r.vmware.manager.VmwareManagerImpl > 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Disconnect to listener: com.cloud.storage.s= econdary.SecondaryStorageListener > 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Disconnect to listener: com.cloud.network.S= shKeysDistriMonitor > 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Disconnect to listener: com.cloud.network.r= outer.VpcVirtualNetworkApplianceManagerImpl > 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Disconnect to listener: com.cloud.agent.man= ager.AgentManagerImpl$BehindOnPingListener > 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Disconnect to listener: com.cloud.storage.d= ownload.DownloadListener > 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Disconnect to listener: com.cloud.network.S= shKeysDistriMonitor > 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Disconnect to listener: com.cloud.network.r= outer.VirtualNetworkApplianceManagerImpl > 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Disconnect to listener: com.cloud.network.N= etworkUsageManagerImpl$DirectNetworkStatsListener > 2015-08-18 06:24:46,546 DEBUG [c.c.n.NetworkUsageManagerImpl] (AgentConne= ctTaskPool-213:ctx-76903ef6) Disconnected called on 27 with status Alert > 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Disconnect to listener: com.cloud.storage.u= pload.UploadListener > 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Disconnect to listener: com.cloud.consolepr= oxy.ConsoleProxyListener > 2015-08-18 06:24:46,547 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Disconnect to listener: com.cloud.storage.L= ocalStoragePoolListener > 2015-08-18 06:24:46,547 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Disconnect to listener: com.cloud.capacity.= StorageCapacityListener > 2015-08-18 06:24:46,547 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Sending Disconnect to listener: com.cloud.capacity.= ComputeCapacityListener > 2015-08-18 06:24:46,547 DEBUG [c.c.h.Status] (AgentConnectTaskPool-213:ct= x-76903ef6) Transition:[Resource state =3D Enabled, Agent event =3D AgentDi= sconnected, Host id =3D 27, name =3D ***.***.***] > 2015-08-18 06:24:46,551 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (AgentC= onnectTaskPool-213:ctx-76903ef6) Notifying other nodes of to disconnect > 2015-08-18 06:24:46,554 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Failed to handle host connection: com.cloud.utils.e= xception.CloudRuntimeException: Unable to connect 27 > 2015-08-18 06:24:46,555 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTas= kPool-213:ctx-76903ef6) Can not send command com.cloud.agent.api.ReadyComma= nd due to Host 27 is not up > --- >8 --- > > Here's what I see on behalf of the agent: > > --- 8< --- > 2015-08-18 06:24:46,199 INFO [cloud.agent.Agent] (Agent-Handler-3:null) = Reconnecting... > 2015-08-18 06:24:46,199 INFO [utils.nio.NioClient] (Agent-Selector:null)= Connecting to ***.***.***.***:8250 > 2015-08-18 06:24:46,287 INFO [utils.nio.NioClient] (Agent-Selector:null)= SSL: Handshake done > 2015-08-18 06:24:46,287 INFO [utils.nio.NioClient] (Agent-Selector:null)= Connected to ***.***.***.***:8250 > 2015-08-18 06:24:46,292 WARN [kvm.resource.LibvirtComputingResource] (Ag= ent-Handler-1:null) Could not read cpuinfo_max_freq > 2015-08-18 06:24:46,317 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-= Handler-1:null) Attempting to create storage pool 51670fbd-ece2-4a3e-9971-3= 928e6576f0e (Filesystem) in libvirt > 2015-08-18 06:24:46,332 INFO [cloud.agent.Agent] (Agent-Handler-2:null) = Proccess agent startup answer, agent id =3D 0 > 2015-08-18 06:24:46,333 INFO [cloud.agent.Agent] (Agent-Handler-2:null) = Set agent id 0 > 2015-08-18 06:24:46,333 INFO [cloud.agent.Agent] (Agent-Handler-2:null) = Startup Response Received: agent id =3D 0 > 2015-08-18 06:24:46,555 WARN [cloud.agent.Agent] (Agent-Handler-5:null) = Unable to send response: null > 2015-08-18 06:24:51,288 INFO [cloud.agent.Agent] (Agent-Handler-3:null) = Connected to the server > 2015-08-18 06:24:51,546 INFO [cloud.agent.Agent] (Agent-Handler-4:null) = Lost connection to the server. Dealing with the remaining commands... > 2015-08-18 06:24:56,547 INFO [utils.nio.NioClient] (Agent-Handler-4:null= ) NioClient connection closed > --- >8--- > > Does anyone have an idea on what's wrong or how to get to know what's > wrong? Thanks a lot! > > -- > V.Melnik > > P.S. It was working fine before we had upgraded from 4.4.2 to 4.5.1. > -- V.Melnik