You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@cloudstack.apache.org by Daznis <da...@gmail.com> on 2018/03/01 08:46:23 UTC
Re: Cloudstack 4.11 fails to add KVM host
Hello,
That's when I shutdown the agent and started from scratch .
On Wed, Feb 28, 2018 at 11:08 PM, Rohit Yadav <ro...@shapeblue.com> wrote:
> Hi Daznis,
>
>
> I see the agent decided to kill itself:
>
> 2018-02-28 03:56:34,183 INFO [cloud.agent.Agent] (AgentShutdownThread:null) (logid:) Stopping the agent: Reason = sig.kill
>
>
> This happens when the management server send a ShutDown command to the agent. Without logs and additional debugging it will be hard to tell, but something went wrong on the management server side. It's possible that the mgmt server decided to kill the agent for failure to add the host.
>
>
> You may re-attempt host addition or you can attempt a fresh installation and share the details if it fails again.
>
>
> - Rohit
>
> <https://cloudstack.apache.org>
>
>
>
> ________________________________
> From: Daznis <da...@gmail.com>
> Sent: Wednesday, February 28, 2018 7:13:54 PM
> To: users@cloudstack.apache.org
> Subject: Re: Cloudstack 4.11 fails to add KVM host
>
> 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.
>
>
>
>
>
>
> rohit.yadav@shapeblue.com
> www.shapeblue.com
> 53 Chandos Place, Covent Garden, London WC2N 4HSUK
> @shapeblue
>
>
>
> On Wed, Feb 28, 2018 at 1:36 PM, Rohit Yadav <ro...@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 <da...@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.yadav@shapeblue.com
>> www.shapeblue.com<http://www.shapeblue.com>
>> 53 Chandos Place, Covent Garden, London WC2N 4HSUK
>> @shapeblue
>>
>>
>>
Re: Cloudstack 4.11 fails to add KVM host
Posted by Daznis <da...@gmail.com>.
Hello,
any updates regarding this issue?
On Fri, Mar 2, 2018 at 11:05 AM, Daznis <da...@gmail.com> wrote:
> Hello,
>
>
> I have attached both log folders here. The installation is done
> manually, to centos 7.4. Management servers run kernel
> 3.10.0-693.17.1.el7.x86_64 , node runs 4.4.116-1.el7.elrepo.x86_64.
> Both nodes have synced time. primary storage is ceph hammer, secondary
> is nfs.
>
> On Thu, Mar 1, 2018 at 4:41 PM, Rohit Yadav <ro...@shapeblue.com> wrote:
>> Hi Daznis. Yes, please share the agent and management server logs for starters. It will depends after we can have an initial look. You may also want to share your ping.timeout and ping.interval settings, and also if both management server and kvm host's time are synced (check ntps, run them). Please also share details of your setup such as kvm and mgmt server distro version (based on the rpm repo, I'm guessint CentOS7), storage type (nfs, localstorage, something else?), how you're deploying the zone (custom script, manually) and any special tags, traffic label you may be using?
>>
>>
>> Hi Parth - what you've shared does not seem like a similar issue like this one. If you KVM host's nic is unplugged at some point it will fail to check storagepool (nfs etc) heartbeat and reboot. This is done to avoid split brain issues, when storage pool may not be reachable. The code that causes this is:
>>
>> https://github.com/apache/cloudstack/blob/master/scripts/vm/hypervisor/kvm/kvmheartbeat.sh#L161
>>
>>
>> - Rohit
>>
>> <https://cloudstack.apache.org>
>>
>>
>>
>> ________________________________
>> From: Daznis <da...@gmail.com>
>> Sent: Thursday, March 1, 2018 12:57:43 PM
>> To: users@cloudstack.apache.org
>> Subject: Re: Cloudstack 4.11 fails to add KVM host
>>
>> Hello,
>>
>>
>>
>> I just finished rebuilding the management server and node and I'm
>> getting the same error. I now have full setup and agent/management
>> server logs if you need the for further investigation. What other
>> things might you need to resolve this issue?
>>
>>
>> rohit.yadav@shapeblue.com
>> www.shapeblue.com
>> 53 Chandos Place, Covent Garden, London WC2N 4HSUK
>> @shapeblue
>>
>>
>>
>> On Thu, Mar 1, 2018 at 10:46 AM, Daznis <da...@gmail.com> wrote:
>>> Hello,
>>>
>>> That's when I shutdown the agent and started from scratch .
>>>
>>> On Wed, Feb 28, 2018 at 11:08 PM, Rohit Yadav <ro...@shapeblue.com> wrote:
>>>> Hi Daznis,
>>>>
>>>>
>>>> I see the agent decided to kill itself:
>>>>
>>>> 2018-02-28 03:56:34,183 INFO [cloud.agent.Agent] (AgentShutdownThread:null) (logid:) Stopping the agent: Reason = sig.kill
>>>>
>>>>
>>>> This happens when the management server send a ShutDown command to the agent. Without logs and additional debugging it will be hard to tell, but something went wrong on the management server side. It's possible that the mgmt server decided to kill the agent for failure to add the host.
>>>>
>>>>
>>>> You may re-attempt host addition or you can attempt a fresh installation and share the details if it fails again.
>>>>
>>>>
>>>> - Rohit
>>>>
>>>> <https://cloudstack.apache.org>
>>>>
>>>>
>>>>
>>>> ________________________________
>>>> From: Daznis <da...@gmail.com>
>>>> Sent: Wednesday, February 28, 2018 7:13:54 PM
>>>> To: users@cloudstack.apache.org
>>>> Subject: Re: Cloudstack 4.11 fails to add KVM host
>>>>
>>>> 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.
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>> rohit.yadav@shapeblue.com
>>>> www.shapeblue.com<http://www.shapeblue.com>
>>>> 53 Chandos Place, Covent Garden, London WC2N 4HSUK
>>>> @shapeblue
>>>>
>>>>
>>>>
>>>> On Wed, Feb 28, 2018 at 1:36 PM, Rohit Yadav <ro...@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 <da...@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.yadav@shapeblue.com
>>>>> www.shapeblue.com<http://www.shapeblue.com>
>>>>> 53 Chandos Place, Covent Garden, London WC2N 4HSUK
>>>>> @shapeblue
>>>>>
>>>>>
>>>>>
<div class="gmail_extra"><br><div class="gmail_quote">On Fri, Mar 2,
2018 at 11:05 AM, Daznis <span dir="ltr"><<a
href="mailto:daznis@gmail.com"
target="_blank">daznis@gmail.com</a>></span> wrote:<br><blockquote
class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc
solid;padding-left:1ex">Hello,<br>
<br>
<br>
I have attached both log folders here. The installation is done<br>
manually, to centos 7.4. Management servers run kernel<br>
3.10.0-693.17.1.el7.x86_64 , node runs 4.4.116-1.el7.elrepo.x86_64.<br>
Both nodes have synced time. primary storage is ceph hammer, secondary<br>
is nfs.<br>
<div class="HOEnZb"><div class="h5"><br>
On Thu, Mar 1, 2018 at 4:41 PM, Rohit Yadav <<a
href="mailto:rohit.yadav@shapeblue.com">rohit.yadav@shapeblue.com</a>>
wrote:<br>
> Hi Daznis. Yes, please share the agent and management server logs
for starters. It will depends after we can have an initial look. You
may also want to share your ping.timeout and ping.interval settings,
and also if both management server and kvm host's time are synced
(check ntps, run them). Please also share details of your setup such
as kvm and mgmt server distro version (based on the rpm repo, I'm
guessint CentOS7), storage type (nfs, localstorage, something else?),
how you're deploying the zone (custom script, manually) and any
special tags, traffic label you may be using?<br>
><br>
><br>
> Hi Parth - what you've shared does not seem like a similar issue
like this one. If you KVM host's nic is unplugged at some point it
will fail to check storagepool (nfs etc) heartbeat and reboot. This is
done to avoid split brain issues, when storage pool may not be
reachable. The code that causes this is:<br>
><br>
> <a href="https://github.com/apache/cloudstack/blob/master/scripts/vm/hypervisor/kvm/kvmheartbeat.sh#L161"
data-saferedirecturl="https://www.google.com/url?hl=en&q=https://github.com/apache/cloudstack/blob/master/scripts/vm/hypervisor/kvm/kvmheartbeat.sh%23L161&source=gmail&ust=1520676273598000&usg=AFQjCNHLyjLCGy1heq13_zoKbOAIfnlW7g"
rel="noreferrer"
target="_blank">https://github.com/apache/<wbr>cloudstack/blob/master/<wbr>scripts/vm/hypervisor/kvm/<wbr>kvmheartbeat.sh#L161</a><br>
><br>
><br>
> - Rohit<br>
><br>
> <<a href="https://cloudstack.apache.org"
data-saferedirecturl="https://www.google.com/url?hl=en&q=https://cloudstack.apache.org&source=gmail&ust=1520676273598000&usg=AFQjCNE1BlrVSWSsEjiNy0OxcU4Bv_X_aQ"
rel="noreferrer"
target="_blank">https://cloudstack.apache.org</a><wbr>><br>
><br>
><br>
><br>
> ______________________________<wbr>__<br>
> From: Daznis <<a
href="mailto:daznis@gmail.com">daznis@gmail.com</a>><br>
> Sent: Thursday, March 1, 2018 12:57:43 PM<br>
> To: <a href="mailto:users@cloudstack.apache.org">users@cloudstack.apache.org</a><br>
> Subject: Re: Cloudstack 4.11 fails to add KVM host<br>
><br>
> Hello,<br>
><br>
><br>
><br>
> I just finished rebuilding the management server and node and I'm<br>
> getting the same error. I now have full setup and agent/management<br>
> server logs if you need the for further investigation. What other<br>
> things might you need to resolve this issue?<br>
><br>
><br>
> <a href="mailto:rohit.yadav@shapeblue.com">rohit.yadav@shapeblue.com</a><br>
> <a href="http://www.shapeblue.com"
data-saferedirecturl="https://www.google.com/url?hl=en&q=http://www.shapeblue.com&source=gmail&ust=1520676273598000&usg=AFQjCNESK6fGYJFTnaw_15OFPVgM6L0Yuw"
rel="noreferrer" target="_blank">www.shapeblue.com</a><br>
> 53 Chandos Place, Covent Garden, London WC2N 4HSUK<br>
> @shapeblue<br>
><br>
><br>
><br>
> On Thu, Mar 1, 2018 at 10:46 AM, Daznis <<a
href="mailto:daznis@gmail.com">daznis@gmail.com</a>> wrote:<br>
>> Hello,<br>
>><br>
>> That's when I shutdown the agent and started from scratch .<br>
>><br>
>> On Wed, Feb 28, 2018 at 11:08 PM, Rohit Yadav <<a
href="mailto:rohit.yadav@shapeblue.com">rohit.yadav@shapeblue.com</a>>
wrote:<br>
>>> Hi Daznis,<br>
>>><br>
>>><br>
>>> I see the agent decided to kill itself:<br>
>>><br>
>>> 2018-02-28 03:56:34,183 INFO [cloud.agent.Agent]
(AgentShutdownThread:null) (logid:) Stopping the agent: Reason =
sig.kill<br>
>>><br>
>>><br>
>>> This happens when the management server send a ShutDown
command to the agent. Without logs and additional debugging it will be
hard to tell, but something went wrong on the management server side.
It's possible that the mgmt server decided to kill the agent for
failure to add the host.<br>
>>><br>
>>><br>
>>> You may re-attempt host addition or you can attempt a
fresh installation and share the details if it fails again.<br>
>>><br>
>>><br>
>>> - Rohit<br>
>>><br>
>>> <<a href="https://cloudstack.apache.org"
data-saferedirecturl="https://www.google.com/url?hl=en&q=https://cloudstack.apache.org&source=gmail&ust=1520676273599000&usg=AFQjCNFR4GO4_hWUSRT9q-7r0RWO4OH1OQ"
rel="noreferrer"
target="_blank">https://cloudstack.apache.org</a><wbr>><br>
>>><br>
>>><br>
>>><br>
>>> ______________________________<wbr>__<br>
>>> From: Daznis <<a
href="mailto:daznis@gmail.com">daznis@gmail.com</a>><br>
>>> Sent: Wednesday, February 28, 2018 7:13:54 PM<br>
>>> To: <a
href="mailto:users@cloudstack.apache.org">users@cloudstack.apache.org</a><br>
>>> Subject: Re: Cloudstack 4.11 fails to add KVM host<br>
>>><br>
>>> Hello,<br>
>>><br>
>>><br>
>>> Unfortunately I didn't have full debug on. So I can't
provide you with<br>
>>> more detailed logs. I currently wiped both the management
and node<br>
>>> servers and started over. If I will encounter the same
issue I will<br>
>>> provide more detailed logs.<br>
>>><br>
>>><br>
>>> Repo:<br>
>>><br>
>>> [cloudstack]<br>
>>> name=cloudstack<br>
>>> baseurl=<a
href="http://cloudstack.apt-get.eu/centos/$releasever/4.11/"
data-saferedirecturl="https://www.google.com/url?hl=en&q=http://cloudstack.apt-get.eu/centos/$releasever/4.11/&source=gmail&ust=1520676273599000&usg=AFQjCNEDVWfgtP81-MataLeKfIIC-1OAPw"
rel="noreferrer"
target="_blank">http://cloudstack.apt-<wbr>get.eu/centos/$releasever/4.<wbr>11/</a><br>
>>> enabled=1<br>
>>> gpgcheck=0<br>
>>><br>
>>><br>
>>> Agent and management log parts attached.<br>
>>><br>
>>><br>
>>><br>
>>><br>
>>><br>
>>><br>
>>> <a
href="mailto:rohit.yadav@shapeblue.com">rohit.yadav@shapeblue.com</a><br>
>>> <a href="http://www.shapeblue.com"
data-saferedirecturl="https://www.google.com/url?hl=en&q=http://www.shapeblue.com&source=gmail&ust=1520676273599000&usg=AFQjCNF9MCp6Bv-fZzoS0ld5pxiSo9-xtg"
rel="noreferrer" target="_blank">www.shapeblue.com</a><<a
href="http://www.shapeblue.com"
data-saferedirecturl="https://www.google.com/url?hl=en&q=http://www.shapeblue.com&source=gmail&ust=1520676273599000&usg=AFQjCNF9MCp6Bv-fZzoS0ld5pxiSo9-xtg"
rel="noreferrer"
target="_blank">http://www.<wbr>shapeblue.com</a>><br>
>>> 53 Chandos Place, Covent Garden, London WC2N 4HSUK<br>
>>> @shapeblue<br>
>>><br>
>>><br>
>>><br>
>>> On Wed, Feb 28, 2018 at 1:36 PM, Rohit Yadav <<a
href="mailto:rohit.yadav@shapeblue.com">rohit.yadav@shapeblue.com</a>>
wrote:<br>
>>>> Hi Daznis,<br>
>>>><br>
>>>><br>
>>>> Can you share full logs when you're trying to add the
KVM host. In the logs, do you see something like:<br>
>>>><br>
>>>> SSH command: lsmod|grep kvm<br>
>>>> Or,<br>
>>>> Executing cmd: cloudstack-setup-agent -m
172.20.0.1 -z 1 -p 1 -c 1 -g 72f644c9-4f58-3048-8e32-<wbr>901d38d30672
-a --pubNic=cloudbr0 --prvNic=cloudbr0 --guestNic=cloudbr0
--hypervisor=kvm<br>
>>>><br>
>>>> I don't see any logs related to
c.c.h.k.d.<wbr>LibvirtServerDiscoverer. Which repository did you use
to install ACS 4.11?<br>
>>>><br>
>>>><br>
>>>> Also, can you share the agent logs (in your KVM
host's, from /var/log/cloudstack/agent/)?<br>
>>>><br>
>>>><br>
>>>> - Rohit<br>
>>>><br>
>>>> <<a href="https://cloudstack.apache.org"
data-saferedirecturl="https://www.google.com/url?hl=en&q=https://cloudstack.apache.org&source=gmail&ust=1520676273600000&usg=AFQjCNFsHDEVQfsMKL5010NWKdbBQj9etQ"
rel="noreferrer"
target="_blank">https://cloudstack.apache.org</a><wbr>><br>
>>>><br>
>>>><br>
>>>><br>
>>>> ______________________________<wbr>__<br>
>>>> From: Daznis <<a
href="mailto:daznis@gmail.com">daznis@gmail.com</a>><br>
>>>> Sent: Wednesday, February 28, 2018 10:42:17 AM<br>
>>>> To: <a
href="mailto:users@cloudstack.apache.org">users@cloudstack.apache.org</a><br>
>>>> Subject: Cloudstack 4.11 fails to add KVM host<br>
>>>><br>
>>>> Hello,<br>
>>>><br>
>>>> I'm trying to setup a test VPC cloudstack
installation and encountered<br>
>>>> an error while adding hosts to the cluster. The host
sort of appears<br>
>>>> to be added, but it's not functioning. Trying to add
the same host I<br>
>>>> get an error that host is already present. Both
management server and<br>
>>>> host are running centos 7.4 with latest updates and
cloudstack 4.11.<br>
>>>><br>
>>>><br>
>>>><br>
>>>><br>
>>>><br>
>>>> management-server.log:<br>
>>>><br>
>>>> 2018-02-28 03:01:47,516 DEBUG [c.c.r.ResourceState]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Resource state<br>
>>>> update: [id = 1; name = chi-phv01; old state =
Creating; event =<br>
>>>> InternalCreated; new state = Enabled]<br>
>>>> 2018-02-28 03:01:47,516 DEBUG [c.c.h.Status]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2) (logid:541691a9)<br>
>>>> Transition:[Resource state = Enabled, Agent event =
AgentConnected,<br>
>>>> Host id = 1, name = chi-phv01]<br>
>>>> 2018-02-28 03:01:47,529 DEBUG
[c.c.a.m.<wbr>ClusteredAgentManagerImpl]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) create<br>
>>>> ClusteredAgentAttache for 1<br>
>>>> 2018-02-28 03:01:47,530 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Sending Connect<br>
>>>> to listener: XcpServerDiscoverer<br>
>>>> 2018-02-28 03:01:47,530 DEBUG
[c.c.h.x.d.<wbr>XcpServerDiscoverer]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Not XenServer<br>
>>>> so moving on.<br>
>>>> 2018-02-28 03:01:47,530 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Sending Connect<br>
>>>> to listener: HypervServerDiscoverer<br>
>>>> 2018-02-28 03:01:47,530 DEBUG
[c.c.h.h.d.<wbr>HypervServerDiscoverer]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Not Hyper-V<br>
>>>> hypervisor, so moving on.<br>
>>>> 2018-02-28 03:01:47,530 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Sending Connect<br>
>>>> to listener: SecondaryStorageListener<br>
>>>> 2018-02-28 03:01:47,530 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Sending Connect<br>
>>>> to listener: StoragePoolMonitor<br>
>>>> 2018-02-28 03:01:47,537 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Sending Connect<br>
>>>> to listener: NetworkOrchestrator<br>
>>>> 2018-02-28 03:01:47,538 DEBUG
[o.a.c.e.o.<wbr>NetworkOrchestrator]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Host's<br>
>>>> hypervisorType is: KVM<br>
>>>> 2018-02-28 03:01:47,544 DEBUG
[o.a.c.e.o.<wbr>NetworkOrchestrator]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Sending<br>
>>>> CheckNetworkCommand to check the Network is setup
correctly on Agent<br>
>>>> 2018-02-28 03:01:47,553 DEBUG [c.c.a.t.Request]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Seq<br>
>>>> 1-6113355019178737665: Sending { Cmd , MgmtId:
2200401215515, via:<br>
>>>> 1(chi-phv01), Ver: v1, Flags: 100111,<br>
>>>>
[{"com.cloud.agent.api.<wbr>CheckNetworkCommand":{"<wbr>networkInfoList":[{"<wbr>physicalNetworkId":200,"<wbr>privateNetworkName":"bond0.57"<wbr>,"publicNetworkName":"bridge-<wbr>bond0","guestNetworkName":"<wbr>bridge-bond0"}],"wait":0}}]<br>
>>>> }<br>
>>>> 2018-02-28 03:01:47,627 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (AgentManager-Handler-3:null) (logid:) Ping from
1(chi-phv01)<br>
>>>> 2018-02-28 03:01:47,628 DEBUG
[c.c.v.<wbr>VirtualMachinePowerStateSyncIm<wbr>pl]<br>
>>>> (AgentManager-Handler-3:null) (logid:) Process host
VM state report<br>
>>>> from ping process. host: 1<br>
>>>> 2018-02-28 03:01:47,628 DEBUG
[c.c.v.<wbr>VirtualMachinePowerStateSyncIm<wbr>pl]<br>
>>>> (AgentManager-Handler-3:null) (logid:) Process VM
state report. host:<br>
>>>> 1, number of records in report: 0<br>
>>>> 2018-02-28 03:01:47,630 DEBUG
[c.c.v.<wbr>VirtualMachinePowerStateSyncIm<wbr>pl]<br>
>>>> (AgentManager-Handler-3:null) (logid:) Done with
process of VM state<br>
>>>> report. host: 1<br>
>>>> 2018-02-28 03:01:47,632 INFO
[c.c.a.m.AgentManagerImpl]<br>
>>>> (AgentManager-Handler-3:null) (logid:) PingMap for
agent: 1 will not<br>
>>>> be updated because agent is no longer in the PingMap<br>
>>>> 2018-02-28 03:01:47,633 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (AgentManager-Handler-3:null) (logid:) Not processing<br>
>>>> PingRoutingCommand for agent id=0; can't find the
host in the DB<br>
>>>> 2018-02-28 03:01:47,738 DEBUG [c.c.a.t.Request]<br>
>>>> (AgentManager-Handler-4:null) (logid:) Seq
1-6113355019178737665:<br>
>>>> Processing: { Ans: , MgmtId: 2200401215515,
via: 1, Ver: v1, Flags:<br>
>>>> 110,
[{"com.cloud.agent.api.<wbr>CheckNetworkAnswer":{"_<wbr>reconnect":false,"result":<wbr>true,"wait":0}}]<br>
>>>> }<br>
>>>> 2018-02-28 03:01:47,739 DEBUG [c.c.a.m.AgentAttache]<br>
>>>> (AgentManager-Handler-4:null) (logid:) Seq
1-6113355019178737665: No<br>
>>>> more commands found<br>
>>>> 2018-02-28 03:01:47,740 DEBUG [c.c.a.t.Request]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Seq<br>
>>>> 1-6113355019178737665: Received: { Ans: ,
MgmtId: 2200401215515, via:<br>
>>>> 1(chi-phv01), Ver: v1, Flags: 110, { CheckNetworkAnswer } }<br>
>>>> 2018-02-28 03:01:47,740 DEBUG
[o.a.c.e.o.<wbr>NetworkOrchestrator]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Network setup<br>
>>>> is correct on Agent<br>
>>>> 2018-02-28 03:01:47,740 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Sending Connect<br>
>>>> to listener: SecurityGroupListener<br>
>>>> 2018-02-28 03:01:47,740 INFO
[c.c.n.s.<wbr>SecurityGroupListener]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Received a host<br>
>>>> startup notification<br>
>>>> 2018-02-28 03:01:47,742 DEBUG [c.c.a.t.Request]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Seq<br>
>>>> 1-6113355019178737666: Sending { Cmd , MgmtId:
2200401215515, via:<br>
>>>> 1(chi-phv01), Ver: v1, Flags: 100011,<br>
>>>>
[{"com.cloud.agent.api.<wbr>CleanupNetworkRulesCmd":{"<wbr>interval":2239,"wait":0}}]<br>
>>>> }<br>
>>>> 2018-02-28 03:01:47,743 INFO
[c.c.n.s.<wbr>SecurityGroupListener]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Scheduled<br>
>>>> network rules cleanup, interval=2239<br>
>>>> 2018-02-28 03:01:47,743 INFO
[c.c.n.s.<wbr>SecurityGroupListener]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Received a host<br>
>>>> startup notification<br>
>>>> 2018-02-28 03:01:47,743 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Sending Connect<br>
>>>> to listener: ClusteredVirtualMachineManager<wbr>Impl<br>
>>>> 2018-02-28 03:01:47,743 DEBUG
[c.c.v.<wbr>VirtualMachineManagerImpl]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Received<br>
>>>> startup command from hypervisor host. host id: 1<br>
>>>> 2018-02-28 03:01:47,743 INFO
[c.c.v.<wbr>VirtualMachinePowerStateSyncIm<wbr>pl]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Reset VM power<br>
>>>> state sync for host: 1<br>
>>>> 2018-02-28 03:01:47,755 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Sending Connect<br>
>>>> to listener: DeploymentPlanningManagerImpl<br>
>>>> 2018-02-28 03:01:47,763 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Sending Connect<br>
>>>> to listener: SshKeysDistriMonitor<br>
>>>> 2018-02-28 03:01:47,769 DEBUG [c.c.a.t.Request]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Seq<br>
>>>> 1-6113355019178737667: Sending { Cmd , MgmtId:
2200401215515, via:<br>
>>>> 1(chi-phv01), Ver: v1, Flags: 100011,<br>
>>>>
[{"com.cloud.agent.api.<wbr>ModifySshKeysCommand":{"wait":<wbr>0}}]
}<br>
>>>> 2018-02-28 03:01:47,769 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Sending Connect<br>
>>>> to listener: VirtualNetworkApplianceManager<wbr>Impl<br>
>>>> 2018-02-28 03:01:47,771 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Sending Connect<br>
>>>> to listener: UploadListener<br>
>>>> 2018-02-28 03:01:47,772 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Sending Connect<br>
>>>> to listener: SshKeysDistriMonitor<br>
>>>> 2018-02-28 03:01:47,776 DEBUG [c.c.a.t.Request]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Seq<br>
>>>> 1-6113355019178737668: Sending { Cmd , MgmtId:
2200401215515, via:<br>
>>>> 1(chi-phv01), Ver: v1, Flags: 100011,<br>
>>>>
[{"com.cloud.agent.api.<wbr>ModifySshKeysCommand":{"wait":<wbr>0}}]
}<br>
>>>> 2018-02-28 03:01:47,776 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Sending Connect<br>
>>>> to listener: VpcVirtualNetworkApplianceMana<wbr>gerImpl<br>
>>>> 2018-02-28 03:01:47,778 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Sending Connect<br>
>>>> to listener: BehindOnPingListener<br>
>>>> 2018-02-28 03:01:47,779 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Sending Connect<br>
>>>> to listener: SetHostParamsListener<br>
>>>> 2018-02-28 03:01:47,781 DEBUG [c.c.a.t.Request]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Seq<br>
>>>> 1-6113355019178737669: Sending { Cmd , MgmtId:
2200401215515, via:<br>
>>>> 1(chi-phv01), Ver: v1, Flags: 100111,<br>
>>>>
[{"com.cloud.agent.api.<wbr>SetHostParamsCommand":{"<wbr>params":{"router.aggregation.<wbr>command.each.timeout":"600"},"<wbr>wait":0}}]<br>
>>>> }<br>
>>>> 2018-02-28 03:01:47,781 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Sending Connect<br>
>>>> to listener: DownloadListener<br>
>>>> 2018-02-28 03:01:47,792 DEBUG [c.c.a.t.Request]<br>
>>>> (AgentManager-Handler-5:null) (logid:) Seq
1-6113355019178737666:<br>
>>>> Processing: { Ans: , MgmtId: 2200401215515,
via: 1, Ver: v1, Flags:<br>
>>>> 10,
[{"com.cloud.agent.api.Answer"<wbr>:{"result":true,"wait":0}}] }<br>
>>>> 2018-02-28 03:01:47,793 DEBUG [c.c.a.t.Request]<br>
>>>> (AgentManager-Handler-6:null) (logid:) Seq
1-6113355019178737667:<br>
>>>> Processing: { Ans: , MgmtId: 2200401215515,
via: 1, Ver: v1, Flags:<br>
>>>> 10,
[{"com.cloud.agent.api.Answer"<wbr>:{"result":true,"wait":0}}] }<br>
>>>> 2018-02-28 03:01:47,833 DEBUG [c.c.a.t.Request]<br>
>>>> (AgentManager-Handler-7:null) (logid:) Seq
1-6113355019178737669:<br>
>>>> Processing: { Ans: , MgmtId: 2200401215515,
via: 1, Ver: v1, Flags:<br>
>>>> 110,
[{"com.cloud.agent.api.Answer"<wbr>:{"result":true,"wait":0}}] }<br>
>>>> 2018-02-28 03:01:47,833 DEBUG [c.c.a.m.AgentAttache]<br>
>>>> (AgentManager-Handler-7:null) (logid:) Seq
1-6113355019178737669: No<br>
>>>> more commands found<br>
>>>> 2018-02-28 03:01:47,834 INFO
[c.c.a.m.<wbr>ClusteredAgentManagerImpl]<br>
>>>> (AgentManager-Handler-7:null) (logid:) SeqA
1-6113355019178737669:<br>
>>>> Response is not processed: Seq
1-6113355019178737669: { Ans: ,<br>
>>>> MgmtId: 2200401215515, via: 1, Ver: v1, Flags: 110,<br>
>>>>
[{"com.cloud.agent.api.Answer"<wbr>:{"result":true,"wait":0}}] }<br>
>>>> 2018-02-28 03:01:47,834 DEBUG [c.c.a.t.Request]<br>
>>>> (AgentManager-Handler-8:null) (logid:) Seq
1-6113355019178737668:<br>
>>>> Processing: { Ans: , MgmtId: 2200401215515,
via: 1, Ver: v1, Flags:<br>
>>>> 10,
[{"com.cloud.agent.api.Answer"<wbr>:{"result":true,"wait":0}}] }<br>
>>>> 2018-02-28 03:01:47,874 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Sending Connect<br>
>>>> to listener: StorageCapacityListener<br>
>>>> 2018-02-28 03:01:47,874 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Sending Connect<br>
>>>> to listener: ComputeCapacityListener<br>
>>>> 2018-02-28 03:01:47,878 DEBUG [c.c.c.CapacityManagerImpl]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Found 0 VMs on<br>
>>>> host 1<br>
>>>> 2018-02-28 03:01:47,882 DEBUG [c.c.c.CapacityManagerImpl]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Found 0 VM, not<br>
>>>> running on host 1<br>
>>>> 2018-02-28 03:01:47,912 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Sending Connect<br>
>>>> to listener: ConsoleProxyListener<br>
>>>> 2018-02-28 03:01:47,912 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Sending Connect<br>
>>>> to listener: LocalStoragePoolListener<br>
>>>> 2018-02-28 03:01:47,914 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Sending Connect<br>
>>>> to listener: DirectNetworkStatsListener<br>
>>>> 2018-02-28 03:01:47,917 DEBUG [c.c.a.t.Request]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Seq<br>
>>>> 1-6113355019178737670: Sending { Cmd , MgmtId:
2200401215515, via:<br>
>>>> 1(chi-phv01), Ver: v1, Flags: 100111,<br>
>>>>
[{"com.cloud.agent.api.<wbr>ReadyCommand":{"dcId":1,"<wbr>hostId":1,"wait":0}}]<br>
>>>> }<br>
>>>> 2018-02-28 03:01:47,951 DEBUG [c.c.a.t.Request]<br>
>>>> (AgentManager-Handler-9:null) (logid:) Seq
1-6113355019178737666:<br>
>>>> Processing: { Ans: , MgmtId: 2200401215515,
via: 1, Ver: v1, Flags:<br>
>>>> 10,
[{"com.cloud.agent.api.Answer"<wbr>:{"result":true,"details":"","<wbr>wait":0}}]<br>
>>>> }<br>
>>>> 2018-02-28 03:01:47,991 DEBUG [c.c.a.t.Request]<br>
>>>> (AgentManager-Handler-10:null) (logid:) Seq
1-6113355019178737670:<br>
>>>> Processing: { Ans: , MgmtId: 2200401215515,
via: 1, Ver: v1, Flags:<br>
>>>> 110,
[{"com.cloud.agent.api.<wbr>ReadyAnswer":{"result":true,"<wbr>wait":0}}]
}<br>
>>>> 2018-02-28 03:01:47,991 DEBUG [c.c.a.m.AgentAttache]<br>
>>>> (AgentManager-Handler-10:null) (logid:) Seq
1-6113355019178737670: No<br>
>>>> more commands found<br>
>>>> 2018-02-28 03:01:47,992 DEBUG [c.c.a.t.Request]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Seq<br>
>>>> 1-6113355019178737670: Received: { Ans: ,
MgmtId: 2200401215515, via:<br>
>>>> 1(chi-phv01), Ver: v1, Flags: 110, { ReadyAnswer } }<br>
>>>> 2018-02-28 03:01:47,992 DEBUG [c.c.h.Status]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2) (logid:541691a9)<br>
>>>> Transition:[Resource state = Enabled, Agent event =
Ready, Host id =<br>
>>>> 1, name = chi-phv01]<br>
>>>> 2018-02-28 03:01:48,014 DEBUG [c.c.a.t.Request]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Seq<br>
>>>> 1-6113355019178737671: Sending { Cmd , MgmtId:
2200401215515, via:<br>
>>>> 1(chi-phv01), Ver: v1, Flags: 100111,<br>
>>>>
[{"com.cloud.agent.api.<wbr>ReadyCommand":{"dcId":1,"<wbr>hostId":1,"wait":0}}]<br>
>>>> }<br>
>>>> 2018-02-28 03:01:48,099 DEBUG [c.c.a.t.Request]<br>
>>>> (AgentManager-Handler-11:null) (logid:) Seq
1-6113355019178737671:<br>
>>>> Processing: { Ans: , MgmtId: 2200401215515,
via: 1, Ver: v1, Flags:<br>
>>>> 110,
[{"com.cloud.agent.api.<wbr>ReadyAnswer":{"result":true,"<wbr>wait":0}}]
}<br>
>>>> 2018-02-28 03:01:48,099 DEBUG [c.c.a.m.AgentAttache]<br>
>>>> (AgentManager-Handler-11:null) (logid:) Seq
1-6113355019178737671: No<br>
>>>> more commands found<br>
>>>> 2018-02-28 03:01:48,099 DEBUG [c.c.a.t.Request]<br>
>>>> (AgentConnectTaskPool-1:ctx-<wbr>e30615f2)
(logid:541691a9) Seq<br>
>>>> 1-6113355019178737671: Received: { Ans: ,
MgmtId: 2200401215515, via:<br>
>>>> 1(chi-phv01), Ver: v1, Flags: 110, { ReadyAnswer } }<br>
>>>> 2018-02-28 03:01:52,741 INFO
[o.a.c.f.j.i.<wbr>AsyncJobManagerImpl]<br>
>>>> (AsyncJobMgr-Heartbeat-1:ctx-<wbr>50530b32)
(logid:28780ab2) Begin cleanup<br>
>>>> expired async-jobs<br>
>>>> 2018-02-28 03:01:52,745 INFO
[o.a.c.f.j.i.<wbr>AsyncJobManagerImpl]<br>
>>>> (AsyncJobMgr-Heartbeat-1:ctx-<wbr>50530b32)
(logid:28780ab2) End cleanup<br>
>>>> expired async-jobs<br>
>>>> 2018-02-28 03:01:58,476 DEBUG
[c.c.c.<wbr>ConsoleProxyManagerImpl]<br>
>>>> (consoleproxy-1:ctx-f0b6d74b) (logid:64b70007) Skip
capacity scan as<br>
>>>> there is no Primary Storage in 'Up' state<br>
>>>> 2018-02-28 03:02:02,741 INFO
[o.a.c.f.j.i.<wbr>AsyncJobManagerImpl]<br>
>>>> (AsyncJobMgr-Heartbeat-1:ctx-<wbr>03121b2c)
(logid:8451c9ee) Begin cleanup<br>
>>>> expired async-jobs<br>
>>>> 2018-02-28 03:02:02,745 INFO
[o.a.c.f.j.i.<wbr>AsyncJobManagerImpl]<br>
>>>> (AsyncJobMgr-Heartbeat-1:ctx-<wbr>03121b2c)
(logid:8451c9ee) End cleanup<br>
>>>> expired async-jobs<br>
>>>> 2018-02-28 03:02:10,933 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f)
(logid:f8587145) Sending<br>
>>>> host added to listener: XcpServerDiscoverer<br>
>>>> 2018-02-28 03:02:10,933 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f)
(logid:f8587145) Sending<br>
>>>> host added to listener: HypervServerDiscoverer<br>
>>>> 2018-02-28 03:02:10,933 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f)
(logid:f8587145) Sending<br>
>>>> host added to listener: SecondaryStorageListener<br>
>>>> 2018-02-28 03:02:10,933 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f)
(logid:f8587145) Sending<br>
>>>> host added to listener: StoragePoolMonitor<br>
>>>> 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f)
(logid:f8587145) Sending<br>
>>>> host added to listener: NetworkOrchestrator<br>
>>>> 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f)
(logid:f8587145) Sending<br>
>>>> host added to listener: SecurityGroupListener<br>
>>>> 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f)
(logid:f8587145) Sending<br>
>>>> host added to listener:
ClusteredVirtualMachineManager<wbr>Impl<br>
>>>> 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f)
(logid:f8587145) Sending<br>
>>>> host added to listener: DeploymentPlanningManagerImpl<br>
>>>> 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f)
(logid:f8587145) Sending<br>
>>>> host added to listener: SshKeysDistriMonitor<br>
>>>> 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f)
(logid:f8587145) Sending<br>
>>>> host added to listener:
VirtualNetworkApplianceManager<wbr>Impl<br>
>>>> 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f)
(logid:f8587145) Sending<br>
>>>> host added to listener: UploadListener<br>
>>>> 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f)
(logid:f8587145) Sending<br>
>>>> host added to listener: SshKeysDistriMonitor<br>
>>>> 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f)
(logid:f8587145) Sending<br>
>>>> host added to listener:
VpcVirtualNetworkApplianceMana<wbr>gerImpl<br>
>>>> 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f)
(logid:f8587145) Sending<br>
>>>> host added to listener: BehindOnPingListener<br>
>>>> 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f)
(logid:f8587145) Sending<br>
>>>> host added to listener: SetHostParamsListener<br>
>>>> 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f)
(logid:f8587145) Sending<br>
>>>> host added to listener: DownloadListener<br>
>>>> 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f)
(logid:f8587145) Sending<br>
>>>> host added to listener: StorageCapacityListener<br>
>>>> 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f)
(logid:f8587145) Sending<br>
>>>> host added to listener: ComputeCapacityListener<br>
>>>> 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f)
(logid:f8587145) Sending<br>
>>>> host added to listener: ConsoleProxyListener<br>
>>>> 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f)
(logid:f8587145) Sending<br>
>>>> host added to listener: LocalStoragePoolListener<br>
>>>> 2018-02-28 03:02:10,946 DEBUG [c.c.a.m.AgentManagerImpl]<br>
>>>> (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f)
(logid:f8587145) Sending<br>
>>>> host added to listener: DirectNetworkStatsListener<br>
>>>> 2018-02-28 03:02:10,949 ERROR [c.c.a.ApiServer]<br>
>>>> (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f)
(logid:f8587145) unhandled<br>
>>>> exception executing api command:
[Ljava.lang.String;@165f3bf2<br>
>>>> java.lang.<wbr>IndexOutOfBoundsException: Index: 0, Size: 0<br>
>>>> at
java.util.ArrayList.<wbr>rangeCheck(ArrayList.java:657)<br>
>>>> at
java.util.ArrayList.get(<wbr>ArrayList.java:433)<br>
>>>> at
com.cloud.api.<wbr>ApiResponseHelper.<wbr>createHostResponse(<wbr>ApiResponseHelper.java:654)<br>
>>>> at
com.cloud.api.<wbr>ApiResponseHelper.<wbr>createHostResponse(<wbr>ApiResponseHelper.java:646)<br>
>>>> at
org.apache.cloudstack.api.<wbr>command.admin.host.AddHostCmd.<wbr>execute(AddHostCmd.java:147)<br>
>>>> at
com.cloud.api.ApiDispatcher.<wbr>dispatch(ApiDispatcher.java:<wbr>150)<br>
>>>> at
com.cloud.api.ApiServer.<wbr>queueCommand(ApiServer.java:<wbr>731)<br>
>>>> at
com.cloud.api.ApiServer.<wbr>handleRequest(ApiServer.java:<wbr>555)<br>
>>>> at
com.cloud.api.ApiServlet.<wbr>processRequestInContext(<wbr>ApiServlet.java:310)<br>
>>>> at
com.cloud.api.ApiServlet$1.<wbr>run(ApiServlet.java:130)<br>
>>>> at
org.apache.cloudstack.managed.<wbr>context.impl.<wbr>DefaultManagedContext$1.call(<wbr>DefaultManagedContext.java:56)<br>
>>>> at
org.apache.cloudstack.managed.<wbr>context.impl.<wbr>DefaultManagedContext.<wbr>callWithContext(<wbr>DefaultManagedContext.java:<wbr>103)<br>
>>>> at
org.apache.cloudstack.managed.<wbr>context.impl.<wbr>DefaultManagedContext.<wbr>runWithContext(<wbr>DefaultManagedContext.java:53)<br>
>>>> at
com.cloud.api.ApiServlet.<wbr>processRequest(ApiServlet.<wbr>java:127)<br>
>>>> at
com.cloud.api.ApiServlet.<wbr>doPost(ApiServlet.java:94)<br>
>>>> at
javax.servlet.http.<wbr>HttpServlet.service(<wbr>HttpServlet.java:706)<br>
>>>> at
javax.servlet.http.<wbr>HttpServlet.service(<wbr>HttpServlet.java:791)<br>
>>>> at
org.eclipse.jetty.servlet.<wbr>ServletHolder.handle(<wbr>ServletHolder.java:852)<br>
>>>> at
org.eclipse.jetty.servlet.<wbr>ServletHandler.doHandle(<wbr>ServletHandler.java:535)<br>
>>>> at
org.eclipse.jetty.server.<wbr>handler.ScopedHandler.handle(<wbr>ScopedHandler.java:143)<br>
>>>> at
org.eclipse.jetty.security.<wbr>SecurityHandler.handle(<wbr>SecurityHandler.java:548)<br>
>>>> at
org.eclipse.jetty.server.<wbr>handler.HandlerWrapper.handle(<wbr>HandlerWrapper.java:132)<br>
>>>> at
org.eclipse.jetty.server.<wbr>handler.ScopedHandler.<wbr>nextHandle(ScopedHandler.java:<wbr>190)<br>
>>>> at
org.eclipse.jetty.server.<wbr>session.SessionHandler.<wbr>doHandle(SessionHandler.java:<wbr>1595)<br>
>>>> at
org.eclipse.jetty.server.<wbr>handler.ScopedHandler.<wbr>nextHandle(ScopedHandler.java:<wbr>188)<br>
>>>> at
org.eclipse.jetty.server.<wbr>handler.ContextHandler.<wbr>doHandle(ContextHandler.java:<wbr>1253)<br>
>>>> at
org.eclipse.jetty.server.<wbr>handler.ScopedHandler.<wbr>nextScope(ScopedHandler.java:<wbr>168)<br>
>>>> at
org.eclipse.jetty.servlet.<wbr>ServletHandler.doScope(<wbr>ServletHandler.java:473)<br>
>>>> at
org.eclipse.jetty.server.<wbr>session.SessionHandler.<wbr>doScope(SessionHandler.java:<wbr>1564)<br>
>>>> at
org.eclipse.jetty.server.<wbr>handler.ScopedHandler.<wbr>nextScope(ScopedHandler.java:<wbr>166)<br>
>>>> at
org.eclipse.jetty.server.<wbr>handler.ContextHandler.<wbr>doScope(ContextHandler.java:<wbr>1155)<br>
>>>> at
org.eclipse.jetty.server.<wbr>handler.ScopedHandler.handle(<wbr>ScopedHandler.java:141)<br>
>>>> at
org.eclipse.jetty.server.<wbr>handler.gzip.GzipHandler.<wbr>handle(GzipHandler.java:527)<br>
>>>> at
org.eclipse.jetty.server.<wbr>handler.HandlerCollection.<wbr>handle(HandlerCollection.java:<wbr>126)<br>
>>>> at
org.eclipse.jetty.server.<wbr>handler.HandlerWrapper.handle(<wbr>HandlerWrapper.java:132)<br>
>>>> at
org.eclipse.jetty.server.<wbr>Server.handle(Server.java:530)<br>
>>>> at
org.eclipse.jetty.server.<wbr>HttpChannel.handle(<wbr>HttpChannel.java:347)<br>
>>>> at
org.eclipse.jetty.server.<wbr>HttpConnection.onFillable(<wbr>HttpConnection.java:256)<br>
>>>> at
org.eclipse.jetty.io.<wbr>AbstractConnection$<wbr>ReadCallback.succeeded(<wbr>AbstractConnection.java:279)<br>
>>>> at
org.eclipse.jetty.io.<wbr>FillInterest.fillable(<wbr>FillInterest.java:102)<br>
>>>> at
org.eclipse.jetty.io.<wbr>ChannelEndPoint$2.run(<wbr>ChannelEndPoint.java:124)<br>
>>>> at
org.eclipse.jetty.util.thread.<wbr>strategy.EatWhatYouKill.<wbr>doProduce(EatWhatYouKill.java:<wbr>247)<br>
>>>> at
org.eclipse.jetty.util.thread.<wbr>strategy.EatWhatYouKill.<wbr>produce(EatWhatYouKill.java:<wbr>140)<br>
>>>> at
org.eclipse.jetty.util.thread.<wbr>strategy.EatWhatYouKill.run(<wbr>EatWhatYouKill.java:131)<br>
>>>> at
org.eclipse.jetty.util.thread.<wbr>ReservedThreadExecutor$<wbr>ReservedThread.run(<wbr>ReservedThreadExecutor.java:<wbr>382)<br>
>>>> at
org.eclipse.jetty.util.thread.<wbr>QueuedThreadPool.runJob(<wbr>QueuedThreadPool.java:708)<br>
>>>> at
org.eclipse.jetty.util.thread.<wbr>QueuedThreadPool$2.run(<wbr>QueuedThreadPool.java:626)<br>
>>>> at
java.lang.Thread.run(Thread.<wbr>java:748)<br>
>>>><br>
>>>><br>
>>>> apilog.log:<br>
>>>> 2018-02-28 03:00:59,314 INFO [a.c.c.a.ApiServer]<br>
>>>> (qtp788117692-10:ctx-5560c2b1 ctx-b98fcd2f)
(logid:0e4de757) (userId=2<br>
>>>> accountId=2
sessionId=<wbr>node0vg1xfc9xvd911ih4h5xpif3ra<wbr>0) 82.135.143.87<br>
>>>> -- POST
command=addCluster&zoneId=<wbr>50a00553-253f-4b60-b39a-<wbr>3da0a6deb9c2&hypervisor=KVM&<wbr>clustertype=CloudManaged&<wbr>podId=4d482c41-8414-47d0-901f-<wbr>cb256888c5f0&clustername=<wbr>PrivateCloudCluster&response=<wbr>json<br>
>>>> 200
{"addclusterresponse":{"count"<wbr>:1,"cluster":[{"id":"b0edbd45-<wbr>f99d-4b0e-a302-364012e1b59e","<wbr>name":"PrivateCloudCluster","<wbr>podid":"4d482c41-8414-47d0-<wbr>901f-cb256888c5f0","podname":"<wbr>PrivateCloudPod","zoneid":"<wbr>50a00553-253f-4b60-b39a-<wbr>3da0a6deb9c2","zonename":"<wbr>PrivateCloud","hypervisortype"<wbr>:"KVM","clustertype":"<wbr>CloudManaged","<wbr>allocationstate":"Enabled","<wbr>managedstate":"Managed","<wbr>cpuovercommitratio":"1.0","<wbr>memoryovercommitratio":"1.0","<wbr>resourcedetails":{"<wbr>memoryOvercommitRatio":"1.0","<wbr>cpuOvercommitRatio":"1.0"}}]}}<br>
>>>> 2018-02-28 03:02:10,954 INFO [a.c.c.a.ApiServer]<br>
>>>> (qtp788117692-15:ctx-8f3b4977 ctx-da6bfb2f)
(logid:f8587145) (userId=2<br>
>>>> accountId=2
sessionId=<wbr>node0vg1xfc9xvd911ih4h5xpif3ra<wbr>0) 82.135.143.87<br>
>>>> -- POST command=addHost&response=json 530 Index:
0, Size: 0<br>
>>>><br>
>>>> <a
href="mailto:rohit.yadav@shapeblue.com">rohit.yadav@shapeblue.com</a><br>
>>>> <a href="http://www.shapeblue.com"
data-saferedirecturl="https://www.google.com/url?hl=en&q=http://www.shapeblue.com&source=gmail&ust=1520676273604000&usg=AFQjCNE4h5yoPP1q-HXBuL2_QheBkC8IdA"
rel="noreferrer" target="_blank">www.shapeblue.com</a><<a
href="http://www.shapeblue.com"
data-saferedirecturl="https://www.google.com/url?hl=en&q=http://www.shapeblue.com&source=gmail&ust=1520676273604000&usg=AFQjCNE4h5yoPP1q-HXBuL2_QheBkC8IdA"
rel="noreferrer"
target="_blank">http://www.<wbr>shapeblue.com</a>><br>
>>>> 53 Chandos Place, Covent Garden, London WC2N 4HSUK<br>
>>>> @shapeblue<br>
>>>><br>
>>>><br>
>>>><br>
</div></div></blockquote></div><br></div>
Re: Cloudstack 4.11 fails to add KVM host
Posted by Daznis <da...@gmail.com>.
Hello,
I have attached both log folders here. The installation is done
manually, to centos 7.4. Management servers run kernel
3.10.0-693.17.1.el7.x86_64 , node runs 4.4.116-1.el7.elrepo.x86_64.
Both nodes have synced time. primary storage is ceph hammer, secondary
is nfs.
On Thu, Mar 1, 2018 at 4:41 PM, Rohit Yadav <ro...@shapeblue.com> wrote:
> Hi Daznis. Yes, please share the agent and management server logs for starters. It will depends after we can have an initial look. You may also want to share your ping.timeout and ping.interval settings, and also if both management server and kvm host's time are synced (check ntps, run them). Please also share details of your setup such as kvm and mgmt server distro version (based on the rpm repo, I'm guessint CentOS7), storage type (nfs, localstorage, something else?), how you're deploying the zone (custom script, manually) and any special tags, traffic label you may be using?
>
>
> Hi Parth - what you've shared does not seem like a similar issue like this one. If you KVM host's nic is unplugged at some point it will fail to check storagepool (nfs etc) heartbeat and reboot. This is done to avoid split brain issues, when storage pool may not be reachable. The code that causes this is:
>
> https://github.com/apache/cloudstack/blob/master/scripts/vm/hypervisor/kvm/kvmheartbeat.sh#L161
>
>
> - Rohit
>
> <https://cloudstack.apache.org>
>
>
>
> ________________________________
> From: Daznis <da...@gmail.com>
> Sent: Thursday, March 1, 2018 12:57:43 PM
> To: users@cloudstack.apache.org
> Subject: Re: Cloudstack 4.11 fails to add KVM host
>
> Hello,
>
>
>
> I just finished rebuilding the management server and node and I'm
> getting the same error. I now have full setup and agent/management
> server logs if you need the for further investigation. What other
> things might you need to resolve this issue?
>
>
> rohit.yadav@shapeblue.com
> www.shapeblue.com
> 53 Chandos Place, Covent Garden, London WC2N 4HSUK
> @shapeblue
>
>
>
> On Thu, Mar 1, 2018 at 10:46 AM, Daznis <da...@gmail.com> wrote:
>> Hello,
>>
>> That's when I shutdown the agent and started from scratch .
>>
>> On Wed, Feb 28, 2018 at 11:08 PM, Rohit Yadav <ro...@shapeblue.com> wrote:
>>> Hi Daznis,
>>>
>>>
>>> I see the agent decided to kill itself:
>>>
>>> 2018-02-28 03:56:34,183 INFO [cloud.agent.Agent] (AgentShutdownThread:null) (logid:) Stopping the agent: Reason = sig.kill
>>>
>>>
>>> This happens when the management server send a ShutDown command to the agent. Without logs and additional debugging it will be hard to tell, but something went wrong on the management server side. It's possible that the mgmt server decided to kill the agent for failure to add the host.
>>>
>>>
>>> You may re-attempt host addition or you can attempt a fresh installation and share the details if it fails again.
>>>
>>>
>>> - Rohit
>>>
>>> <https://cloudstack.apache.org>
>>>
>>>
>>>
>>> ________________________________
>>> From: Daznis <da...@gmail.com>
>>> Sent: Wednesday, February 28, 2018 7:13:54 PM
>>> To: users@cloudstack.apache.org
>>> Subject: Re: Cloudstack 4.11 fails to add KVM host
>>>
>>> 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.
>>>
>>>
>>>
>>>
>>>
>>>
>>> rohit.yadav@shapeblue.com
>>> www.shapeblue.com<http://www.shapeblue.com>
>>> 53 Chandos Place, Covent Garden, London WC2N 4HSUK
>>> @shapeblue
>>>
>>>
>>>
>>> On Wed, Feb 28, 2018 at 1:36 PM, Rohit Yadav <ro...@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 <da...@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.yadav@shapeblue.com
>>>> www.shapeblue.com<http://www.shapeblue.com>
>>>> 53 Chandos Place, Covent Garden, London WC2N 4HSUK
>>>> @shapeblue
>>>>
>>>>
>>>>
Re: Cloudstack 4.11 fails to add KVM host
Posted by Rohit Yadav <ro...@shapeblue.com>.
Hi Daznis. Yes, please share the agent and management server logs for starters. It will depends after we can have an initial look. You may also want to share your ping.timeout and ping.interval settings, and also if both management server and kvm host's time are synced (check ntps, run them). Please also share details of your setup such as kvm and mgmt server distro version (based on the rpm repo, I'm guessint CentOS7), storage type (nfs, localstorage, something else?), how you're deploying the zone (custom script, manually) and any special tags, traffic label you may be using?
Hi Parth - what you've shared does not seem like a similar issue like this one. If you KVM host's nic is unplugged at some point it will fail to check storagepool (nfs etc) heartbeat and reboot. This is done to avoid split brain issues, when storage pool may not be reachable. The code that causes this is:
https://github.com/apache/cloudstack/blob/master/scripts/vm/hypervisor/kvm/kvmheartbeat.sh#L161
- Rohit
<https://cloudstack.apache.org>
________________________________
From: Daznis <da...@gmail.com>
Sent: Thursday, March 1, 2018 12:57:43 PM
To: users@cloudstack.apache.org
Subject: Re: Cloudstack 4.11 fails to add KVM host
Hello,
I just finished rebuilding the management server and node and I'm
getting the same error. I now have full setup and agent/management
server logs if you need the for further investigation. What other
things might you need to resolve this issue?
rohit.yadav@shapeblue.comÂ
www.shapeblue.com
53 Chandos Place, Covent Garden, London WC2N 4HSUK
@shapeblue
On Thu, Mar 1, 2018 at 10:46 AM, Daznis <da...@gmail.com> wrote:
> Hello,
>
> That's when I shutdown the agent and started from scratch .
>
> On Wed, Feb 28, 2018 at 11:08 PM, Rohit Yadav <ro...@shapeblue.com> wrote:
>> Hi Daznis,
>>
>>
>> I see the agent decided to kill itself:
>>
>> 2018-02-28 03:56:34,183 INFO [cloud.agent.Agent] (AgentShutdownThread:null) (logid:) Stopping the agent: Reason = sig.kill
>>
>>
>> This happens when the management server send a ShutDown command to the agent. Without logs and additional debugging it will be hard to tell, but something went wrong on the management server side. It's possible that the mgmt server decided to kill the agent for failure to add the host.
>>
>>
>> You may re-attempt host addition or you can attempt a fresh installation and share the details if it fails again.
>>
>>
>> - Rohit
>>
>> <https://cloudstack.apache.org>
>>
>>
>>
>> ________________________________
>> From: Daznis <da...@gmail.com>
>> Sent: Wednesday, February 28, 2018 7:13:54 PM
>> To: users@cloudstack.apache.org
>> Subject: Re: Cloudstack 4.11 fails to add KVM host
>>
>> 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.
>>
>>
>>
>>
>>
>>
>> rohit.yadav@shapeblue.com
>> www.shapeblue.com<http://www.shapeblue.com>
>> 53 Chandos Place, Covent Garden, London WC2N 4HSUK
>> @shapeblue
>>
>>
>>
>> On Wed, Feb 28, 2018 at 1:36 PM, Rohit Yadav <ro...@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 <da...@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.yadav@shapeblue.com
>>> www.shapeblue.com<http://www.shapeblue.com>
>>> 53 Chandos Place, Covent Garden, London WC2N 4HSUK
>>> @shapeblue
>>>
>>>
>>>
Re: Cloudstack 4.11 fails to add KVM host
Posted by Daznis <da...@gmail.com>.
Hello,
I just finished rebuilding the management server and node and I'm
getting the same error. I now have full setup and agent/management
server logs if you need the for further investigation. What other
things might you need to resolve this issue?
On Thu, Mar 1, 2018 at 10:46 AM, Daznis <da...@gmail.com> wrote:
> Hello,
>
> That's when I shutdown the agent and started from scratch .
>
> On Wed, Feb 28, 2018 at 11:08 PM, Rohit Yadav <ro...@shapeblue.com> wrote:
>> Hi Daznis,
>>
>>
>> I see the agent decided to kill itself:
>>
>> 2018-02-28 03:56:34,183 INFO [cloud.agent.Agent] (AgentShutdownThread:null) (logid:) Stopping the agent: Reason = sig.kill
>>
>>
>> This happens when the management server send a ShutDown command to the agent. Without logs and additional debugging it will be hard to tell, but something went wrong on the management server side. It's possible that the mgmt server decided to kill the agent for failure to add the host.
>>
>>
>> You may re-attempt host addition or you can attempt a fresh installation and share the details if it fails again.
>>
>>
>> - Rohit
>>
>> <https://cloudstack.apache.org>
>>
>>
>>
>> ________________________________
>> From: Daznis <da...@gmail.com>
>> Sent: Wednesday, February 28, 2018 7:13:54 PM
>> To: users@cloudstack.apache.org
>> Subject: Re: Cloudstack 4.11 fails to add KVM host
>>
>> 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.
>>
>>
>>
>>
>>
>>
>> rohit.yadav@shapeblue.com
>> www.shapeblue.com
>> 53 Chandos Place, Covent Garden, London WC2N 4HSUK
>> @shapeblue
>>
>>
>>
>> On Wed, Feb 28, 2018 at 1:36 PM, Rohit Yadav <ro...@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 <da...@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.yadav@shapeblue.com
>>> www.shapeblue.com<http://www.shapeblue.com>
>>> 53 Chandos Place, Covent Garden, London WC2N 4HSUK
>>> @shapeblue
>>>
>>>
>>>