Hello,
Unfortunately I didn't have full debug on. So I can't provide you with more detailed logs. I currently wiped both the management and node servers and started over. If I will encounter the same issue I will provide more detailed logs. Repo: [cloudstack] name=cloudstack baseurl=http://cloudstack.apt-get.eu/centos/$releasever/4.11/ enabled=1 gpgcheck=0 Agent and management log parts attached. On Wed, Feb 28, 2018 at 1:36 PM, Rohit Yadav <rohit.ya...@shapeblue.com> wrote: > Hi Daznis, > > > Can you share full logs when you're trying to add the KVM host. In the logs, > do you see something like: > > SSH command: lsmod|grep kvm > Or, > Executing cmd: cloudstack-setup-agent -m 172.20.0.1 -z 1 -p 1 -c 1 -g > 72f644c9-4f58-3048-8e32-901d38d30672 -a --pubNic=cloudbr0 --prvNic=cloudbr0 > --guestNic=cloudbr0 --hypervisor=kvm > > I don't see any logs related to c.c.h.k.d.LibvirtServerDiscoverer. Which > repository did you use to install ACS 4.11? > > > Also, can you share the agent logs (in your KVM host's, from > /var/log/cloudstack/agent/)? > > > - Rohit > > <https://cloudstack.apache.org> > > > > ________________________________ > From: Daznis <daz...@gmail.com> > Sent: Wednesday, February 28, 2018 10:42:17 AM > To: users@cloudstack.apache.org > Subject: Cloudstack 4.11 fails to add KVM host > > Hello, > > I'm trying to setup a test VPC cloudstack installation and encountered > an error while adding hosts to the cluster. The host sort of appears > to be added, but it's not functioning. Trying to add the same host I > get an error that host is already present. Both management server and > host are running centos 7.4 with latest updates and cloudstack 4.11. > > > > > > management-server.log: > > 2018-02-28 03:01:47,516 DEBUG [c.c.r.ResourceState] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Resource state > update: [id = 1; name = chi-phv01; old state = Creating; event = > InternalCreated; new state = Enabled] > 2018-02-28 03:01:47,516 DEBUG [c.c.h.Status] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) > Transition:[Resource state = Enabled, Agent event = AgentConnected, > Host id = 1, name = chi-phv01] > 2018-02-28 03:01:47,529 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) create > ClusteredAgentAttache for 1 > 2018-02-28 03:01:47,530 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Sending Connect > to listener: XcpServerDiscoverer > 2018-02-28 03:01:47,530 DEBUG [c.c.h.x.d.XcpServerDiscoverer] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Not XenServer > so moving on. > 2018-02-28 03:01:47,530 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Sending Connect > to listener: HypervServerDiscoverer > 2018-02-28 03:01:47,530 DEBUG [c.c.h.h.d.HypervServerDiscoverer] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Not Hyper-V > hypervisor, so moving on. > 2018-02-28 03:01:47,530 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Sending Connect > to listener: SecondaryStorageListener > 2018-02-28 03:01:47,530 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Sending Connect > to listener: StoragePoolMonitor > 2018-02-28 03:01:47,537 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Sending Connect > to listener: NetworkOrchestrator > 2018-02-28 03:01:47,538 DEBUG [o.a.c.e.o.NetworkOrchestrator] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Host's > hypervisorType is: KVM > 2018-02-28 03:01:47,544 DEBUG [o.a.c.e.o.NetworkOrchestrator] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Sending > CheckNetworkCommand to check the Network is setup correctly on Agent > 2018-02-28 03:01:47,553 DEBUG [c.c.a.t.Request] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Seq > 1-6113355019178737665: Sending { Cmd , MgmtId: 2200401215515, via: > 1(chi-phv01), Ver: v1, Flags: 100111, > [{"com.cloud.agent.api.CheckNetworkCommand":{"networkInfoList":[{"physicalNetworkId":200,"privateNetworkName":"bond0.57","publicNetworkName":"bridge-bond0","guestNetworkName":"bridge-bond0"}],"wait":0}}] > } > 2018-02-28 03:01:47,627 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentManager-Handler-3:null) (logid:) Ping from 1(chi-phv01) > 2018-02-28 03:01:47,628 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] > (AgentManager-Handler-3:null) (logid:) Process host VM state report > from ping process. host: 1 > 2018-02-28 03:01:47,628 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] > (AgentManager-Handler-3:null) (logid:) Process VM state report. host: > 1, number of records in report: 0 > 2018-02-28 03:01:47,630 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] > (AgentManager-Handler-3:null) (logid:) Done with process of VM state > report. host: 1 > 2018-02-28 03:01:47,632 INFO [c.c.a.m.AgentManagerImpl] > (AgentManager-Handler-3:null) (logid:) PingMap for agent: 1 will not > be updated because agent is no longer in the PingMap > 2018-02-28 03:01:47,633 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentManager-Handler-3:null) (logid:) Not processing > PingRoutingCommand for agent id=0; can't find the host in the DB > 2018-02-28 03:01:47,738 DEBUG [c.c.a.t.Request] > (AgentManager-Handler-4:null) (logid:) Seq 1-6113355019178737665: > Processing: { Ans: , MgmtId: 2200401215515, via: 1, Ver: v1, Flags: > 110, > [{"com.cloud.agent.api.CheckNetworkAnswer":{"_reconnect":false,"result":true,"wait":0}}] > } > 2018-02-28 03:01:47,739 DEBUG [c.c.a.m.AgentAttache] > (AgentManager-Handler-4:null) (logid:) Seq 1-6113355019178737665: No > more commands found > 2018-02-28 03:01:47,740 DEBUG [c.c.a.t.Request] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Seq > 1-6113355019178737665: Received: { Ans: , MgmtId: 2200401215515, via: > 1(chi-phv01), Ver: v1, Flags: 110, { CheckNetworkAnswer } } > 2018-02-28 03:01:47,740 DEBUG [o.a.c.e.o.NetworkOrchestrator] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Network setup > is correct on Agent > 2018-02-28 03:01:47,740 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Sending Connect > to listener: SecurityGroupListener > 2018-02-28 03:01:47,740 INFO [c.c.n.s.SecurityGroupListener] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Received a host > startup notification > 2018-02-28 03:01:47,742 DEBUG [c.c.a.t.Request] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Seq > 1-6113355019178737666: Sending { Cmd , MgmtId: 2200401215515, via: > 1(chi-phv01), Ver: v1, Flags: 100011, > [{"com.cloud.agent.api.CleanupNetworkRulesCmd":{"interval":2239,"wait":0}}] > } > 2018-02-28 03:01:47,743 INFO [c.c.n.s.SecurityGroupListener] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Scheduled > network rules cleanup, interval=2239 > 2018-02-28 03:01:47,743 INFO [c.c.n.s.SecurityGroupListener] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Received a host > startup notification > 2018-02-28 03:01:47,743 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Sending Connect > to listener: ClusteredVirtualMachineManagerImpl > 2018-02-28 03:01:47,743 DEBUG [c.c.v.VirtualMachineManagerImpl] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Received > startup command from hypervisor host. host id: 1 > 2018-02-28 03:01:47,743 INFO [c.c.v.VirtualMachinePowerStateSyncImpl] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Reset VM power > state sync for host: 1 > 2018-02-28 03:01:47,755 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Sending Connect > to listener: DeploymentPlanningManagerImpl > 2018-02-28 03:01:47,763 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Sending Connect > to listener: SshKeysDistriMonitor > 2018-02-28 03:01:47,769 DEBUG [c.c.a.t.Request] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Seq > 1-6113355019178737667: Sending { Cmd , MgmtId: 2200401215515, via: > 1(chi-phv01), Ver: v1, Flags: 100011, > [{"com.cloud.agent.api.ModifySshKeysCommand":{"wait":0}}] } > 2018-02-28 03:01:47,769 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Sending Connect > to listener: VirtualNetworkApplianceManagerImpl > 2018-02-28 03:01:47,771 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Sending Connect > to listener: UploadListener > 2018-02-28 03:01:47,772 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Sending Connect > to listener: SshKeysDistriMonitor > 2018-02-28 03:01:47,776 DEBUG [c.c.a.t.Request] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Seq > 1-6113355019178737668: Sending { Cmd , MgmtId: 2200401215515, via: > 1(chi-phv01), Ver: v1, Flags: 100011, > [{"com.cloud.agent.api.ModifySshKeysCommand":{"wait":0}}] } > 2018-02-28 03:01:47,776 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Sending Connect > to listener: VpcVirtualNetworkApplianceManagerImpl > 2018-02-28 03:01:47,778 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Sending Connect > to listener: BehindOnPingListener > 2018-02-28 03:01:47,779 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Sending Connect > to listener: SetHostParamsListener > 2018-02-28 03:01:47,781 DEBUG [c.c.a.t.Request] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Seq > 1-6113355019178737669: Sending { Cmd , MgmtId: 2200401215515, via: > 1(chi-phv01), Ver: v1, Flags: 100111, > [{"com.cloud.agent.api.SetHostParamsCommand":{"params":{"router.aggregation.command.each.timeout":"600"},"wait":0}}] > } > 2018-02-28 03:01:47,781 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Sending Connect > to listener: DownloadListener > 2018-02-28 03:01:47,792 DEBUG [c.c.a.t.Request] > (AgentManager-Handler-5:null) (logid:) Seq 1-6113355019178737666: > Processing: { Ans: , MgmtId: 2200401215515, via: 1, Ver: v1, Flags: > 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] } > 2018-02-28 03:01:47,793 DEBUG [c.c.a.t.Request] > (AgentManager-Handler-6:null) (logid:) Seq 1-6113355019178737667: > Processing: { Ans: , MgmtId: 2200401215515, via: 1, Ver: v1, Flags: > 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] } > 2018-02-28 03:01:47,833 DEBUG [c.c.a.t.Request] > (AgentManager-Handler-7:null) (logid:) Seq 1-6113355019178737669: > Processing: { Ans: , MgmtId: 2200401215515, via: 1, Ver: v1, Flags: > 110, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] } > 2018-02-28 03:01:47,833 DEBUG [c.c.a.m.AgentAttache] > (AgentManager-Handler-7:null) (logid:) Seq 1-6113355019178737669: No > more commands found > 2018-02-28 03:01:47,834 INFO [c.c.a.m.ClusteredAgentManagerImpl] > (AgentManager-Handler-7:null) (logid:) SeqA 1-6113355019178737669: > Response is not processed: Seq 1-6113355019178737669: { Ans: , > MgmtId: 2200401215515, via: 1, Ver: v1, Flags: 110, > [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] } > 2018-02-28 03:01:47,834 DEBUG [c.c.a.t.Request] > (AgentManager-Handler-8:null) (logid:) Seq 1-6113355019178737668: > Processing: { Ans: , MgmtId: 2200401215515, via: 1, Ver: v1, Flags: > 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] } > 2018-02-28 03:01:47,874 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Sending Connect > to listener: StorageCapacityListener > 2018-02-28 03:01:47,874 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Sending Connect > to listener: ComputeCapacityListener > 2018-02-28 03:01:47,878 DEBUG [c.c.c.CapacityManagerImpl] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Found 0 VMs on > host 1 > 2018-02-28 03:01:47,882 DEBUG [c.c.c.CapacityManagerImpl] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Found 0 VM, not > running on host 1 > 2018-02-28 03:01:47,912 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Sending Connect > to listener: ConsoleProxyListener > 2018-02-28 03:01:47,912 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Sending Connect > to listener: LocalStoragePoolListener > 2018-02-28 03:01:47,914 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Sending Connect > to listener: DirectNetworkStatsListener > 2018-02-28 03:01:47,917 DEBUG [c.c.a.t.Request] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Seq > 1-6113355019178737670: Sending { Cmd , MgmtId: 2200401215515, via: > 1(chi-phv01), Ver: v1, Flags: 100111, > [{"com.cloud.agent.api.ReadyCommand":{"dcId":1,"hostId":1,"wait":0}}] > } > 2018-02-28 03:01:47,951 DEBUG [c.c.a.t.Request] > (AgentManager-Handler-9:null) (logid:) Seq 1-6113355019178737666: > Processing: { Ans: , MgmtId: 2200401215515, via: 1, Ver: v1, Flags: > 10, [{"com.cloud.agent.api.Answer":{"result":true,"details":"","wait":0}}] > } > 2018-02-28 03:01:47,991 DEBUG [c.c.a.t.Request] > (AgentManager-Handler-10:null) (logid:) Seq 1-6113355019178737670: > Processing: { Ans: , MgmtId: 2200401215515, via: 1, Ver: v1, Flags: > 110, [{"com.cloud.agent.api.ReadyAnswer":{"result":true,"wait":0}}] } > 2018-02-28 03:01:47,991 DEBUG [c.c.a.m.AgentAttache] > (AgentManager-Handler-10:null) (logid:) Seq 1-6113355019178737670: No > more commands found > 2018-02-28 03:01:47,992 DEBUG [c.c.a.t.Request] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Seq > 1-6113355019178737670: Received: { Ans: , MgmtId: 2200401215515, via: > 1(chi-phv01), Ver: v1, Flags: 110, { ReadyAnswer } } > 2018-02-28 03:01:47,992 DEBUG [c.c.h.Status] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) > Transition:[Resource state = Enabled, Agent event = Ready, Host id = > 1, name = chi-phv01] > 2018-02-28 03:01:48,014 DEBUG [c.c.a.t.Request] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Seq > 1-6113355019178737671: Sending { Cmd , MgmtId: 2200401215515, via: > 1(chi-phv01), Ver: v1, Flags: 100111, > [{"com.cloud.agent.api.ReadyCommand":{"dcId":1,"hostId":1,"wait":0}}] > } > 2018-02-28 03:01:48,099 DEBUG [c.c.a.t.Request] > (AgentManager-Handler-11:null) (logid:) Seq 1-6113355019178737671: > Processing: { Ans: , MgmtId: 2200401215515, via: 1, Ver: v1, Flags: > 110, [{"com.cloud.agent.api.ReadyAnswer":{"result":true,"wait":0}}] } > 2018-02-28 03:01:48,099 DEBUG [c.c.a.m.AgentAttache] > (AgentManager-Handler-11:null) (logid:) Seq 1-6113355019178737671: No > more commands found > 2018-02-28 03:01:48,099 DEBUG [c.c.a.t.Request] > (AgentConnectTaskPool-1:ctx-e30615f2) (logid:541691a9) Seq > 1-6113355019178737671: Received: { Ans: , MgmtId: 2200401215515, via: > 1(chi-phv01), Ver: v1, Flags: 110, { ReadyAnswer } } > 2018-02-28 03:01:52,741 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] > (AsyncJobMgr-Heartbeat-1:ctx-50530b32) (logid:28780ab2) Begin cleanup > expired async-jobs > 2018-02-28 03:01:52,745 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] > (AsyncJobMgr-Heartbeat-1:ctx-50530b32) (logid:28780ab2) End cleanup > expired async-jobs > 2018-02-28 03:01:58,476 DEBUG [c.c.c.ConsoleProxyManagerImpl] > (consoleproxy-1:ctx-f0b6d74b) (logid:64b70007) Skip capacity scan as > there is no Primary Storage in 'Up' state > 2018-02-28 03:02:02,741 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] > (AsyncJobMgr-Heartbeat-1:ctx-03121b2c) (logid:8451c9ee) Begin cleanup > expired async-jobs > 2018-02-28 03:02:02,745 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] > (AsyncJobMgr-Heartbeat-1:ctx-03121b2c) (logid:8451c9ee) End cleanup > expired async-jobs > 2018-02-28 03:02:10,933 DEBUG [c.c.a.m.AgentManagerImpl] > (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f) (logid:f8587145) Sending > host added to listener: XcpServerDiscoverer > 2018-02-28 03:02:10,933 DEBUG [c.c.a.m.AgentManagerImpl] > (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f) (logid:f8587145) Sending > host added to listener: HypervServerDiscoverer > 2018-02-28 03:02:10,933 DEBUG [c.c.a.m.AgentManagerImpl] > (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f) (logid:f8587145) Sending > host added to listener: SecondaryStorageListener > 2018-02-28 03:02:10,933 DEBUG [c.c.a.m.AgentManagerImpl] > (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f) (logid:f8587145) Sending > host added to listener: StoragePoolMonitor > 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl] > (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f) (logid:f8587145) Sending > host added to listener: NetworkOrchestrator > 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl] > (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f) (logid:f8587145) Sending > host added to listener: SecurityGroupListener > 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl] > (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f) (logid:f8587145) Sending > host added to listener: ClusteredVirtualMachineManagerImpl > 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl] > (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f) (logid:f8587145) Sending > host added to listener: DeploymentPlanningManagerImpl > 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl] > (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f) (logid:f8587145) Sending > host added to listener: SshKeysDistriMonitor > 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl] > (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f) (logid:f8587145) Sending > host added to listener: VirtualNetworkApplianceManagerImpl > 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl] > (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f) (logid:f8587145) Sending > host added to listener: UploadListener > 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl] > (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f) (logid:f8587145) Sending > host added to listener: SshKeysDistriMonitor > 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl] > (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f) (logid:f8587145) Sending > host added to listener: VpcVirtualNetworkApplianceManagerImpl > 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl] > (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f) (logid:f8587145) Sending > host added to listener: BehindOnPingListener > 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl] > (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f) (logid:f8587145) Sending > host added to listener: SetHostParamsListener > 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl] > (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f) (logid:f8587145) Sending > host added to listener: DownloadListener > 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl] > (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f) (logid:f8587145) Sending > host added to listener: StorageCapacityListener > 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl] > (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f) (logid:f8587145) Sending > host added to listener: ComputeCapacityListener > 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl] > (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f) (logid:f8587145) Sending > host added to listener: ConsoleProxyListener > 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl] > (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f) (logid:f8587145) Sending > host added to listener: LocalStoragePoolListener > 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl] > (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f) (logid:f8587145) Sending > host added to listener: DirectNetworkStatsListener > 2018-02-28 03:02:10,949 ERROR [c.c.a.ApiServer] > (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f) (logid:f8587145) unhandled > exception executing api command: [Ljava.lang.String;@165f3bf2 > java.lang.IndexOutOfBoundsException: Index: 0, Size: 0 > at java.util.ArrayList.rangeCheck(ArrayList.java:657) > at java.util.ArrayList.get(ArrayList.java:433) > at > com.cloud.api.ApiResponseHelper.createHostResponse(ApiResponseHelper.java:654) > at > com.cloud.api.ApiResponseHelper.createHostResponse(ApiResponseHelper.java:646) > at > org.apache.cloudstack.api.command.admin.host.AddHostCmd.execute(AddHostCmd.java:147) > at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:150) > at com.cloud.api.ApiServer.queueCommand(ApiServer.java:731) > at com.cloud.api.ApiServer.handleRequest(ApiServer.java:555) > at > com.cloud.api.ApiServlet.processRequestInContext(ApiServlet.java:310) > at com.cloud.api.ApiServlet$1.run(ApiServlet.java:130) > at > org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56) > at > org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103) > at > org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53) > at com.cloud.api.ApiServlet.processRequest(ApiServlet.java:127) > at com.cloud.api.ApiServlet.doPost(ApiServlet.java:94) > at javax.servlet.http.HttpServlet.service(HttpServlet.java:706) > at javax.servlet.http.HttpServlet.service(HttpServlet.java:791) > at > org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:852) > at > org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:535) > at > org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) > at > org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) > at > org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) > at > org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:190) > at > org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595) > at > org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188) > at > org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1253) > at > org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:168) > at > org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473) > at > org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564) > at > org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:166) > at > org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1155) > at > org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) > at > org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:527) > at > org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:126) > at > org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) > at org.eclipse.jetty.server.Server.handle(Server.java:530) > at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:347) > at > org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:256) > at > org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279) > at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102) > at > org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124) > at > org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:247) > at > org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:140) > at > org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) > at > org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:382) > at > org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:708) > at > org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:626) > at java.lang.Thread.run(Thread.java:748) > > > apilog.log: > 2018-02-28 03:00:59,314 INFO [a.c.c.a.ApiServer] > (qtp788117692-10:ctx-5560c2b1 ctx-b98fcd2f) (logid:0e4de757) (userId=2 > accountId=2 sessionId=node0vg1xfc9xvd911ih4h5xpif3ra0) 82.135.143.87 > -- POST > command=addCluster&zoneId=50a00553-253f-4b60-b39a-3da0a6deb9c2&hypervisor=KVM&clustertype=CloudManaged&podId=4d482c41-8414-47d0-901f-cb256888c5f0&clustername=PrivateCloudCluster&response=json > 200 > {"addclusterresponse":{"count":1,"cluster":[{"id":"b0edbd45-f99d-4b0e-a302-364012e1b59e","name":"PrivateCloudCluster","podid":"4d482c41-8414-47d0-901f-cb256888c5f0","podname":"PrivateCloudPod","zoneid":"50a00553-253f-4b60-b39a-3da0a6deb9c2","zonename":"PrivateCloud","hypervisortype":"KVM","clustertype":"CloudManaged","allocationstate":"Enabled","managedstate":"Managed","cpuovercommitratio":"1.0","memoryovercommitratio":"1.0","resourcedetails":{"memoryOvercommitRatio":"1.0","cpuOvercommitRatio":"1.0"}}]}} > 2018-02-28 03:02:10,954 INFO [a.c.c.a.ApiServer] > (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f) (logid:f8587145) (userId=2 > accountId=2 sessionId=node0vg1xfc9xvd911ih4h5xpif3ra0) 82.135.143.87 > -- POST command=addHost&response=json 530 Index: 0, Size: 0 > > rohit.ya...@shapeblue.com > www.shapeblue.com > 53 Chandos Place, Covent Garden, London WC2N 4HSUK > @shapeblue > > >
2018-02-28 03:01:44,865 INFO [cloud.agent.AgentShell] (main:null) (logid:) Agent started 2018-02-28 03:01:44,875 INFO [cloud.agent.AgentShell] (main:null) (logid:) Implementation Version is 4.11.0.0 2018-02-28 03:01:44,885 INFO [cloud.agent.AgentShell] (main:null) (logid:) agent.properties found at /etc/cloudstack/agent/agent.properties 2018-02-28 03:01:44,889 INFO [cloud.agent.AgentShell] (main:null) (logid:) Defaulting to using properties file for storage 2018-02-28 03:01:44,890 INFO [cloud.agent.AgentShell] (main:null) (logid:) Defaulting to the constant time backoff algorithm 2018-02-28 03:01:44,915 INFO [cloud.utils.LogUtils] (main:null) (logid:) log4j configuration found at /etc/cloudstack/agent/log4j-cloud.xml 2018-02-28 03:01:44,928 INFO [cloud.agent.AgentShell] (main:null) (logid:) Using default Java settings for IPv6 preference for agent connection 2018-02-28 03:01:45,267 INFO [cloud.agent.Agent] (main:null) (logid:) id is 2018-02-28 03:01:45,350 INFO [kvm.resource.LibvirtConnection] (main:null) (logid:) No existing libvirtd connection found. Opening a new one 2018-02-28 03:01:45,928 INFO [org.reflections.Reflections] (main:null) (logid:) Reflections took 112 ms to scan 1 urls, producing 7 keys and 10 values 2018-02-28 03:01:45,968 INFO [kvm.resource.LibvirtComputingResource] (main:null) (logid:) No libvirt.vif.driver specified. Defaults to BridgeVifDriver. 2018-02-28 03:01:46,342 INFO [cloud.agent.Agent] (main:null) (logid:) Agent [id = new : type = LibvirtComputingResource : zone = 1 : pod = 1 : workers = 5 : host = 10.24.91.2 : port = 8250 2018-02-28 03:01:46,377 INFO [utils.nio.NioClient] (main:null) (logid:) Connecting to 10.24.91.2:8250 2018-02-28 03:01:46,386 INFO [utils.nio.Link] (main:null) (logid:) Conf file found: /etc/cloudstack/agent/agent.properties 2018-02-28 03:01:46,866 INFO [utils.nio.NioClient] (main:null) (logid:) SSL: Handshake done 2018-02-28 03:01:46,866 INFO [utils.nio.NioClient] (main:null) (logid:) Connected to 10.24.91.2:8250 2018-02-28 03:01:47,264 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:null) (logid:) Attempting to create storage pool d982f065-af0b-4ca6-8355-08c525e1f6f2 (Filesystem) in libvirt 2018-02-28 03:01:47,272 WARN [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:null) (logid:) Storage pool d982f065-af0b-4ca6-8355-08c525e1f6f2 was not found running in libvirt. Need to create it. 2018-02-28 03:01:47,272 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:null) (logid:) Didn't find an existing storage pool d982f065-af0b-4ca6-8355-08c525e1f6f2 by UUID, checking for pools with duplicate paths 2018-02-28 03:01:47,277 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:null) (logid:) Trying to fetch storage pool d982f065-af0b-4ca6-8355-08c525e1f6f2 from libvirt 2018-02-28 03:01:47,367 INFO [cloud.serializer.GsonHelper] (Agent-Handler-1:null) (logid:) Default Builder inited. 2018-02-28 03:01:47,421 INFO [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Proccess agent startup answer, agent id = 0 2018-02-28 03:01:47,421 INFO [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Set agent id 0 2018-02-28 03:01:47,428 INFO [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Startup Response Received: agent id = 0 2018-02-28 03:01:47,587 INFO [org.reflections.Reflections] (agentRequest-Handler-1:null) (logid:541691a9) Reflections took 25 ms to scan 1 urls, producing 5 keys and 143 values 2018-02-28 03:01:47,949 INFO [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:541691a9) Proccess agent ready command, agent id = 1 2018-02-28 03:01:47,949 INFO [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:541691a9) Set agent id 1 2018-02-28 03:01:47,950 INFO [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:541691a9) Ready command is processed: agent id = 1 2018-02-28 03:01:48,053 INFO [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:541691a9) Proccess agent ready command, agent id = 1 2018-02-28 03:01:48,053 INFO [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:541691a9) Set agent id 1 2018-02-28 03:01:48,054 INFO [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:541691a9) Ready command is processed: agent id = 1 2018-02-28 03:56:34,183 INFO [cloud.agent.Agent] (AgentShutdownThread:null) (logid:) Stopping the agent: Reason = sig.kill
