Do you have any dynamic service offerings?
________________________________________
From: Vladimir Melnik <[email protected]>
Sent: Thursday, August 20, 2015 8:20 AM
To: [email protected]
Subject: Re: The agent doesn't reconnect if there are stopped VMs
Oh, I'm sorry, I should have initially send the DEBUG-log!
Here is an example:
--- 8< ---
2015-07-29 00:53:42,988 INFO [utils.nio.NioClient] (Agent-Selector:null)
Connecting to ***.***.***.***:8250
2015-07-29 00:53:44,254 INFO [utils.nio.NioClient] (Agent-Selector:null) SSL:
Handshake done
2015-07-29 00:53:44,255 INFO [utils.nio.NioClient] (Agent-Selector:null)
Connected to ***.***.***.***:8250
2015-07-29 00:53:44,258 WARN [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) Could not read cpuinfo_max_freq
2015-07-29 00:53:44,266 DEBUG [kvm.resource.LibvirtCapXMLParser]
(Agent-Handler-1:null) Found /usr/libexec/qemu-kvm as a suiteable emulat
or
2015-07-29 00:53:44,266 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) Executing: /bin/bash -c qemu-img --help|grep
convert
2015-07-29 00:53:44,270 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) Execution is successful.
2015-07-29 00:53:44,271 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) convert [-c] [-p] [-f fmt] [-t cache] [-T
src_cache] [-O output_fmt] [-o options] [-S sparse_size] filename [filename2
[...]] output_filename
2015-07-29 00:53:44,271 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) cpus=8, speed=2660, ram=30153224192, dom0ram
=805306368, cpu sockets=1
2015-07-29 00:53:44,272 DEBUG [cloud.resource.ServerResourceBase]
(Agent-Handler-1:null) Parameters for private nic: 172.26.65.1 - 84:2b:
2b:56:d3:d9-255.255.255.0
2015-07-29 00:53:44,272 DEBUG [cloud.resource.ServerResourceBase]
(Agent-Handler-1:null) Parameters for storage nic: 172.26.65.1 - 84:2b:
2b:56:d3:d9-255.255.255.0
2015-07-29 00:53:44,272 DEBUG [cloud.resource.ServerResourceBase]
(Agent-Handler-1:null) Parameters for pubic nic: 172.26.65.1 - 84:2b:2b
:56:d3:d9-255.255.255.0
2015-07-29 00:53:44,272 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) Executing: /usr/share/cloudstack-common/scri
pts/vm/hypervisor/versions.sh
2015-07-29 00:53:44,281 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) Execution is successful.
2015-07-29 00:53:44,282 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) Executing: sudo grep InitiatorName= /etc/isc
si/initiatorname.iscsi
2015-07-29 00:53:44,290 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) Execution is successful.
2015-07-29 00:53:44,290 INFO [kvm.storage.LibvirtStorageAdaptor]
(Agent-Handler-1:null) Attempting to create storage pool 42bed7d9-88ae-
403d-9b53-0b44f31b2312 (Filesystem) in libvirt
2015-07-29 00:53:44,292 DEBUG [kvm.storage.LibvirtStorageAdaptor]
(Agent-Handler-1:null) Found existing defined storage pool 42bed7d9-88a
e-403d-9b53-0b44f31b2312, using it.
2015-07-29 00:53:44,292 DEBUG [kvm.storage.LibvirtStorageAdaptor]
(Agent-Handler-1:null) Trying to fetch storage pool
42bed7d9-88ae-403d-9b53-0b44f31b2312 from libvirt
2015-07-29 00:53:44,811 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
Executing: hostname
2015-07-29 00:53:44,813 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
Execution is successful.
2015-07-29 00:53:44,834 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
Executing: hostname
2015-07-29 00:53:44,836 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
Execution is successful.
2015-07-29 00:53:44,838 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
Sending Startup: Seq 0-64: { Cmd , MgmtId: -1, via: 0, Ver: v1, Flags: 1,
[{"com.cloud.agent.api.StartupRoutingCommand":{"cpuSockets":1,"cpus":8,"speed":2660,"memory":30153224192,"dom0MinMemory":805306368,"poolSync":false,"caps":"hvm,snapshot","pool":"/root","hypervisorType":"KVM","hostDetails":{"com.cloud.network.Networks.RouterPrivateIpStrategy":"HostLocal","Host.OS":"CentOS","Host.OS.Kernel.Version":"2.6.32-504.16.2.el6.x86_64","Host.OS.Version":"6.6"},"hostTags":[],"groupDetails":{},"type":"Routing","dataCenter":"4","pod":"5","cluster":"5","guid":"26e2bf7d-2fcf-3a67-a23d-ce9c09ef2ca5-LibvirtComputingResource","name":"***.***.***","id":0,"version":"4.5.1","iqn":"iqn.1994-05.com.redhat:f044a5e741a1","publicIpAddress":"172.26.65.1","publicNetmask":"255.255.255.0","publicMacAddress":"84:2b:2b:56:d3:d9","privateIpAddress":"172.26.65.1","privateMacAddress":"84:2b:2b:56:d3:d9","privateNetmask":"255.255.255.0","storageIpAddress":"172.26.65.1","storageNetmask":"255.255.255.0","storageMacAddress":"84:2b:2b:56:d3:d9","resourceName":"LibvirtComputingResource","gatewayIpAddress":"103.247.149.1","wait":0}},{"com.cloud.agent.api.StartupStorageCommand":{"totalSize":0,"poolInfo":{"uuid":"42bed7d9-88ae-403d-9b53-0b44f31b2312","host":"172.26.65.1","localPath":"/var/lib/libvirt/images","hostPath":"/var/lib/libvirt/images","poolType":"Filesystem","capacityBytes":913829568512,"availableBytes":810211274752},"resourceType":"STORAGE_POOL","hostDetails":{},"type":"Storage","dataCenter":"4","pod":"5","guid":"26e2bf7d-2fcf-3a67-a23d-ce9c09ef2ca5-LibvirtComputingResource","name":"***.***.***","id":0,"version":"4.5.1","resourceName":"LibvirtComputingResource","wait":0}}]
}
2015-07-29 00:53:44,838 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
Startup task created
2015-07-29 00:53:45,552 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null)
Received response: Seq 0-64: { Ans: , MgmtId: 279278805451086, via: -1, Ver:
v1, Flags: 100000,
[{"com.cloud.agent.api.StartupAnswer":{"hostId":0,"pingInterval":60,"result":true,"wait":0}}]
}
2015-07-29 00:53:45,553 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null)
Startup task cancelled
2015-07-29 00:53:45,553 INFO [cloud.agent.Agent] (Agent-Handler-2:null)
Proccess agent startup answer, agent id = 0
2015-07-29 00:53:45,553 INFO [cloud.agent.Agent] (Agent-Handler-2:null) Set
agent id 0
2015-07-29 00:53:45,553 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null)
Request:Seq 22-7511722703477276673: { Cmd , MgmtId: 279278805451086, via: 22,
Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.CheckNetworkCommand":{"networkInfoList":[{"physicalNetworkId":203}],"wait":0}}]
}
2015-07-29 00:53:45,553 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null)
Processing command: com.cloud.agent.api.CheckNetworkCommand
2015-07-29 00:53:45,553 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null) Adding
a watch list
2015-07-29 00:53:45,553 INFO [cloud.agent.Agent] (Agent-Handler-2:null)
Startup Response Received: agent id = 0
2015-07-29 00:53:45,554 DEBUG [kvm.resource.LibvirtComputingResource]
(UgentTask-5:null) Executing:
/usr/share/cloudstack-common/scripts/vm/network/security_group.py
get_rule_logs_for_vms
2015-07-29 00:53:45,554 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null)
Seq 22-7511722703477276673: { Ans: , MgmtId: 279278805451086, via: 22, Ver:
v1, Flags: 110,
[{"com.cloud.agent.api.CheckNetworkAnswer":{"_reconnect":false,"result":true,"wait":0}}]
}
2015-07-29 00:53:45,635 DEBUG [kvm.resource.LibvirtComputingResource]
(UgentTask-5:null) Execution is successful.
2015-07-29 00:53:45,638 DEBUG [cloud.agent.Agent] (UgentTask-5:null) Sending
ping: Seq 0-65: { Cmd , MgmtId: -1, via: 0, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.PingRoutingWithNwGroupsCommand":{"newGroupStates":{},"_hostVmStateReport":{},"_gatewayAccessible":true,"_vnetAccessible":true,"hostType":"Routing","hostId":0,"wait":0}}]
}
2015-07-29 00:53:46,084 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:null)
Request:Seq 22-7511722703477276674: { Cmd , MgmtId: 279278805451086, via: 22,
Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.CleanupNetworkRulesCmd":{"interval":2299,"wait":0}}] }
2015-07-29 00:53:46,084 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:null)
Processing command: com.cloud.agent.api.CleanupNetworkRulesCmd
2015-07-29 00:53:46,084 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:null)
Adding a watch list
2015-07-29 00:53:46,084 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) Executing:
/usr/share/cloudstack-common/scripts/vm/network/security_group.py cleanup_rules
2015-07-29 00:53:46,084 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:null)
Seq 22-7511722703477276674: { Ans: , MgmtId: 279278805451086, via: 22, Ver:
v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2015-07-29 00:53:46,084 DEBUG [cloud.agent.Agent] (Agent-Handler-5:null)
Received response: Seq 0-65: { Ans: , MgmtId: 279278805451086, via: 22, Ver:
v1, Flags: 100010,
[{"com.cloud.agent.api.PingAnswer":{"_command":{"hostType":"Routing","hostId":0,"wait":0},"result":true,"wait":0}}]
}
2015-07-29 00:53:46,159 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null)
Request:Seq 22-7511722703477276675: { Cmd , MgmtId: 279278805451086, via: 22,
Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.ModifySshKeysCommand":{"wait":0}}] }
2015-07-29 00:53:46,160 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null)
Processing command: com.cloud.agent.api.ModifySshKeysCommand
2015-07-29 00:53:46,160 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-1:null) Executing: chmod 600 /root/.ssh/id_rsa.cloud
2015-07-29 00:53:46,161 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-1:null) Execution is successful.
2015-07-29 00:53:46,162 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null)
Seq 22-7511722703477276675: { Ans: , MgmtId: 279278805451086, via: 22, Ver:
v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2015-07-29 00:53:46,177 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) Execution is successful.
2015-07-29 00:53:46,178 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null) Watch
Sent: Seq 22-7511722703477276674: { Ans: , MgmtId: 279278805451086, via: 22,
Ver: v1, Flags: 10,
[{"com.cloud.agent.api.Answer":{"result":true,"details":"","wait":0}}] }
2015-07-29 00:53:46,195 DEBUG [utils.nio.NioConnection] (Agent-Selector:null)
Location 1: Socket Socket[addr=/***.***.***.***,port=8250,localport=59991]
closed on read. Probably -1 returned: Connection closed with -1 on reading
size.
2015-07-29 00:53:46,196 DEBUG [utils.nio.NioConnection] (Agent-Selector:null)
Closing socket Socket[addr=/***.***.***.***,port=8250,localport=59991]
2015-07-29 00:53:46,196 DEBUG [cloud.agent.Agent] (Agent-Handler-4:null)
Clearing watch list: 2
2015-07-29 00:53:46,196 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null)
Request:Seq 22-7511722703477276676: { Cmd , MgmtId: 279278805451086, via: 22,
Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.ModifySshKeysCommand":{"wait":0}}] }
2015-07-29 00:53:46,196 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null)
Processing command: com.cloud.agent.api.ModifySshKeysCommand
2015-07-29 00:53:46,197 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-2:null) Executing: chmod 600 /root/.ssh/id_rsa.cloud
2015-07-29 00:53:46,198 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-2:null) Execution is successful.
2015-07-29 00:53:46,199 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null)
Seq 22-7511722703477276676: { Ans: , MgmtId: 279278805451086, via: 22, Ver:
v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2015-07-29 00:53:46,199 WARN [cloud.agent.Agent] (agentRequest-Handler-2:null)
Unable to send response: Seq 22-7511722703477276676: { Ans: , MgmtId:
279278805451086, via: 22, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2015-07-29 00:53:49,255 INFO [cloud.agent.Agent] (Agent-Handler-4:null)
Connected to the server
2015-07-29 00:53:51,196 INFO [cloud.agent.Agent] (Agent-Handler-4:null) Lost
connection to the server. Dealing with the remaining commands...
2015-07-29 00:53:56,198 INFO [utils.nio.NioClient] (Agent-Handler-4:null)
NioClient connection closed
--- >8 ---
It seems that the connection is being closed by the management-server,
but I don't see why.
On Thu, Aug 20, 2015 at 12:53:33PM +0000, Simon Weller wrote:
> Vladimir,
>
> Could you turn up debugging on the agent and post another agent log?
>
> You can do this by running: sed -i 's/INFO/DEBUG/g'
> /etc/cloudstack/agent/log4j-cloud.xml
> Then restart the agent.
>
> - Si
> ________________________________________
> From: Vladimir Melnik <[email protected]>
> Sent: Thursday, August 20, 2015 4:36 AM
> To: [email protected]
> Subject: The agent doesn't reconnect if there are stopped VMs
>
> Dear colleagues,
>
> I have a simple setup where the management server (CentOS-6.6 +
> ACS-4.5.1) is orchestrating a bunch of KVM hosts (each of them is
> running CentOS-6.6 + ACS-4.5.1 as well).
>
> Any host with at least one VM in the "Stopped" state can't reconnect to
> the management server. It has the "Alert" state and here's what I see in
> the management server's log-file:
>
> --- 8< ---
> 2015-08-18 06:24:46,332 DEBUG [c.c.a.t.Request]
> (AgentConnectTaskPool-213:ctx-76903ef6) Seq 0-148: Processing the first
> command { Cmd ,
> MgmtId: -1, via: 0, Ver: v1, Flags: 1,
> [{"com.cloud.agent.api.StartupRoutingCommand":{"cpuSockets":1,"cpus":48,"speed":2299,"memory":6743
> 9632384,"dom0MinMemory":805306368,"poolSync":false,"caps":"hvm,snapshot","pool":"/root","hypervisorType":"KVM","hostDetails":{"com.cloud.
> network.Networks.RouterPrivateIpStrategy":"HostLocal","Host.OS":"CentOS","Host.OS.Kernel.Version":"2.6.32-504.23.4.el6.x86_64","Host.OS.V
> ersion":"6.6"},"hostTags":[],"groupDetails":{},"type":"Routing","dataCenter":"6","pod":"7","cluster":"7","guid":"1318c38d-4ed6-3296-a6bd-753676e25ad4-LibvirtComputingResource","name":"***.***.***","id":0,"version":"4.5.1","publicIpAddress":"172.27.65.1","publicNetmask":"255.255.255.0","publicMacAddress":"ec:f4:bb:d6:89:c5","privateIpAddress":"172.27.65.1","privateMacAddress":"ec:f4:bb:d6:89:c5","privateNetmask":"255.255.255.0","storageIpAddress":"172.27.65.1","storageNetmask":"255.255.255.0","storageMacAddress":"ec:f4:bb:d6:89:c5","resourceName":"LibvirtComputingResource","gatewayIpAddress":"***.***.***.***","wait":0}},{"com.cloud.agent.api.StartupStorageCommand":{"totalSize":0,"poolInfo":{"uuid":"51670fbd-ece2-4a3e-9971-3928e6576f0e","host":"172.27.65.1","localPath":"/var/lib/libvirt/images","hostPath":"/var/lib/libvirt/images","poolType":"Filesystem","capacityBytes":1563804868608,"availableBytes":1474368700416},"resourceType":"STORAGE_POOL","hostDetails":{},"type":"Storage","dataCenter":"6","pod":"7","guid":"1318c38d-4ed6-3296-a6bd-753676e25ad4-LibvirtComputingResource","name":"***.***.***","id":0,"version":"4.5.1","resourceName":"LibvirtComputingResource","wait":0}}]
> }
> 2015-08-18 06:24:46,336 DEBUG [c.c.r.ResourceManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Dispatching resource state event
> CREATE_HOST_VO_FOR_CONNECTED to BaremetalDhcpManagerImpl
> 2015-08-18 06:24:46,336 DEBUG [c.c.r.ResourceManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Dispatching resource state event
> CREATE_HOST_VO_FOR_CONNECTED to BaremetalPxeManagerImpl
> 2015-08-18 06:24:46,336 DEBUG [c.c.r.ResourceManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Dispatching resource state event
> CREATE_HOST_VO_FOR_CONNECTED to NetworkUsageManagerImpl
> 2015-08-18 06:24:46,336 DEBUG [c.c.r.ResourceManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Dispatching resource state event
> CREATE_HOST_VO_FOR_CONNECTED to NuageVspElement
> 2015-08-18 06:24:46,336 DEBUG [c.c.r.ResourceManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Dispatching resource state event
> CREATE_HOST_VO_FOR_CONNECTED to Ovs
> 2015-08-18 06:24:46,336 DEBUG [c.c.r.ResourceManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Dispatching resource state event
> CREATE_HOST_VO_FOR_CONNECTED to PaloAltoExternalFirewallElement
> 2015-08-18 06:24:46,336 DEBUG [c.c.r.ResourceManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Dispatching resource state event
> CREATE_HOST_VO_FOR_CONNECTED to GloboDnsElement
> 2015-08-18 06:24:46,336 DEBUG [c.c.r.ResourceManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Dispatching resource state event
> CREATE_HOST_VO_FOR_CONNECTED to KvmServerDiscoverer
> 2015-08-18 06:24:46,362 DEBUG [c.c.r.ResourceState]
> (AgentConnectTaskPool-213:ctx-76903ef6) Resource state update: [id = 27; name
> = ***.***.***; old state = Enabled; event = InternalCreated; new state =
> Enabled]
> 2015-08-18 06:24:46,362 DEBUG [c.c.h.Status]
> (AgentConnectTaskPool-213:ctx-76903ef6) Transition:[Resource state = Enabled,
> Agent event = AgentConnected, Host id = 27, name = ***.***.***]
> 2015-08-18 06:24:46,365 DEBUG [c.c.a.m.ClusteredAgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) create ClusteredAgentAttache for 27
> 2015-08-18 06:24:46,367 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Connect to listener:
> XcpServerDiscoverer
> 2015-08-18 06:24:46,367 DEBUG [c.c.h.x.d.XcpServerDiscoverer]
> (AgentConnectTaskPool-213:ctx-76903ef6) Not XenServer so moving on.
> 2015-08-18 06:24:46,367 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Connect to listener:
> HypervServerDiscoverer
> 2015-08-18 06:24:46,367 DEBUG [c.c.h.h.d.HypervServerDiscoverer]
> (AgentConnectTaskPool-213:ctx-76903ef6) Not Hyper-V hypervisor, so moving on.
> 2015-08-18 06:24:46,367 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Connect to listener:
> ClusteredVirtualMachineManagerImpl
> 2015-08-18 06:24:46,367 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Received startup command from
> hypervisor host. host id: 27
> 2015-08-18 06:24:46,367 INFO [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Reset VM power state sync for host: 27
> 2015-08-18 06:24:46,369 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Connect to listener:
> NetworkOrchestrator
> 2015-08-18 06:24:46,371 DEBUG [o.a.c.e.o.NetworkOrchestrator]
> (AgentConnectTaskPool-213:ctx-76903ef6) Host's hypervisorType is: KVM
> 2015-08-18 06:24:46,376 DEBUG [o.a.c.e.o.NetworkOrchestrator]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending CheckNetworkCommand to check
> the Network is setup correctly on Agent
> 2015-08-18 06:24:46,379 DEBUG [c.c.a.t.Request]
> (AgentConnectTaskPool-213:ctx-76903ef6) Seq 27-1186417026835415041: Sending
> { Cmd , MgmtId: 279278805451086, via: 27(***.***.***), Ver: v1, Flags:
> 100111,
> [{"com.cloud.agent.api.CheckNetworkCommand":{"networkInfoList":[{"physicalNetworkId":205}],"wait":0}}]
> }
> 2015-08-18 06:24:46,421 DEBUG [c.c.a.t.Request]
> (AgentManager-Handler-15:null) Seq 27-1186417026835415041: Processing: {
> Ans: , MgmtId: 279278805451086, via: 27, Ver: v1, Flags: 110,
> [{"com.cloud.agent.api.CheckNetworkAnswer":{"_reconnect":false,"result":true,"wait":0}}]
> }
> 2015-08-18 06:24:46,422 DEBUG [c.c.a.t.Request]
> (AgentConnectTaskPool-213:ctx-76903ef6) Seq 27-1186417026835415041: Received:
> { Ans: , MgmtId: 279278805451086, via: 27, Ver: v1, Flags: 110, {
> CheckNetworkAnswer } }
> 2015-08-18 06:24:46,422 DEBUG [c.c.a.m.AgentAttache]
> (AgentManager-Handler-15:null) Seq 27-1186417026835415041: No more commands
> found
> 2015-08-18 06:24:46,422 DEBUG [o.a.c.e.o.NetworkOrchestrator]
> (AgentConnectTaskPool-213:ctx-76903ef6) Network setup is correct on Agent
> 2015-08-18 06:24:46,422 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Connect to listener:
> SecurityGroupListener
> 2015-08-18 06:24:46,422 INFO [c.c.n.s.SecurityGroupListener]
> (AgentConnectTaskPool-213:ctx-76903ef6) Received a host startup notification
> 2015-08-18 06:24:46,424 DEBUG [c.c.a.t.Request]
> (AgentConnectTaskPool-213:ctx-76903ef6) Seq 27-1186417026835415042: Sending
> { Cmd , MgmtId: 279278805451086, via: 27(***.***.***), Ver: v1, Flags:
> 100011,
> [{"com.cloud.agent.api.CleanupNetworkRulesCmd":{"interval":2417,"wait":0}}] }
> 2015-08-18 06:24:46,424 INFO [c.c.n.s.SecurityGroupListener]
> (AgentConnectTaskPool-213:ctx-76903ef6) Scheduled network rules cleanup,
> interval=2417
> 2015-08-18 06:24:46,424 INFO [c.c.n.s.SecurityGroupListener]
> (AgentConnectTaskPool-213:ctx-76903ef6) Received a host startup notification
> 2015-08-18 06:24:46,424 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Connect to listener:
> StoragePoolMonitor
> 2015-08-18 06:24:46,428 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Connect to listener:
> DeploymentPlanningManagerImpl
> 2015-08-18 06:24:46,429 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Connect to listener:
> VmwareManagerImpl
> 2015-08-18 06:24:46,429 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Connect to listener:
> SecondaryStorageListener
> 2015-08-18 06:24:46,429 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Connect to listener:
> SshKeysDistriMonitor
> 2015-08-18 06:24:46,433 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentManager-Handler-13:null) Ping from 27
> 2015-08-18 06:24:46,433 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-13:null) Process host VM state report from ping
> process. host: 27
> 2015-08-18 06:24:46,434 DEBUG [c.c.a.t.Request]
> (AgentConnectTaskPool-213:ctx-76903ef6) Seq 27-1186417026835415043: Sending
> { Cmd , MgmtId: 279278805451086, via: 27(***.***.***), Ver: v1, Flags:
> 100011, [{"com.cloud.agent.api.ModifySshKeysCommand":{"wait":0}}] }
> 2015-08-18 06:24:46,435 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Connect to listener:
> VpcVirtualNetworkApplianceManagerImpl
> 2015-08-18 06:24:46,436 DEBUG [c.c.a.t.Request] (AgentManager-Handler-6:null)
> Seq 27-1186417026835415042: Processing: { Ans: , MgmtId: 279278805451086,
> via: 27, Ver: v1, Flags: 10,
> [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
> 2015-08-18 06:24:46,438 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Connect to listener:
> BehindOnPingListener
> 2015-08-18 06:24:46,438 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Connect to listener:
> DownloadListener
> 2015-08-18 06:24:46,447 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-13:null) Process VM state report. host: 27, number of
> records in report: 5
> 2015-08-18 06:24:46,447 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-13:null) VM state report. host: 27, vm id: 1032, power
> state: PowerOn
> 2015-08-18 06:24:46,451 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-13:null) VM state report is updated. host: 27, vm id:
> 1032, power state: PowerOn
> 2015-08-18 06:24:46,457 DEBUG [c.c.c.CapacityManagerImpl]
> (AgentManager-Handler-13:null) VM state transitted from :Running to Running
> with event: FollowAgentPowerOnReportvm's original host id: 27 new host id: 27
> host id before state transition: 27
> 2015-08-18 06:24:46,458 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-13:null) VM state report. host: 27, vm id: 1033, power
> state: PowerOn
> 2015-08-18 06:24:46,469 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-13:null) VM state report is updated. host: 27, vm id:
> 1033, power state: PowerOn
> 2015-08-18 06:24:46,474 DEBUG [c.c.c.CapacityManagerImpl]
> (AgentManager-Handler-13:null) VM state transitted from :Running to Running
> with event: FollowAgentPowerOnReportvm's original host id: 27 new host id: 27
> host id before state transition: 27
> 2015-08-18 06:24:46,475 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-13:null) VM state report. host: 27, vm id: 1038, power
> state: PowerOn
> 2015-08-18 06:24:46,478 DEBUG [c.c.a.t.Request]
> (AgentManager-Handler-10:null) Seq 27-1186417026835415043: Processing: {
> Ans: , MgmtId: 279278805451086, via: 27, Ver: v1, Flags: 10,
> [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
> 2015-08-18 06:24:46,479 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-13:null) VM state report is updated. host: 27, vm id:
> 1038, power state: PowerOn
> 2015-08-18 06:24:46,484 DEBUG [c.c.c.CapacityManagerImpl]
> (AgentManager-Handler-13:null) VM state transitted from :Running to Running
> with event: FollowAgentPowerOnReportvm's original host id: 27 new host id: 27
> host id before state transition: 27
> 2015-08-18 06:24:46,485 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-13:null) VM state report. host: 27, vm id: 1029, power
> state: PowerOn
> 2015-08-18 06:24:46,488 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-13:null) VM state report is updated. host: 27, vm id:
> 1029, power state: PowerOn
> 2015-08-18 06:24:46,493 DEBUG [c.c.c.CapacityManagerImpl]
> (AgentManager-Handler-13:null) VM state transitted from :Running to Running
> with event: FollowAgentPowerOnReportvm's original host id: 27 new host id: 27
> host id before state transition: 27
> 2015-08-18 06:24:46,494 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-13:null) VM state report. host: 27, vm id: 1030, power
> state: PowerOn
> 2015-08-18 06:24:46,497 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-13:null) VM state report is updated. host: 27, vm id:
> 1030, power state: PowerOn
> 2015-08-18 06:24:46,502 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Connect to listener:
> SshKeysDistriMonitor
> 2015-08-18 06:24:46,502 DEBUG [c.c.c.CapacityManagerImpl]
> (AgentManager-Handler-13:null) VM state transitted from :Running to Running
> with event: FollowAgentPowerOnReportvm's original host id: 27 new host id: 27
> host id before state transition: 27
> 2015-08-18 06:24:46,507 DEBUG [c.c.a.t.Request]
> (AgentConnectTaskPool-213:ctx-76903ef6) Seq 27-1186417026835415044: Sending
> { Cmd , MgmtId: 279278805451086, via: 27(***.***.***), Ver: v1, Flags:
> 100011, [{"com.cloud.agent.api.ModifySshKeysCommand":{"wait":0}}] }
> 2015-08-18 06:24:46,507 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Connect to listener:
> VirtualNetworkApplianceManagerImpl
> 2015-08-18 06:24:46,509 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Connect to listener:
> DirectNetworkStatsListener
> 2015-08-18 06:24:46,509 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Connect to listener:
> UploadListener
> 2015-08-18 06:24:46,509 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Connect to listener:
> ConsoleProxyListener
> 2015-08-18 06:24:46,509 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Connect to listener:
> LocalStoragePoolListener
> 2015-08-18 06:24:46,510 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (AgentManager-Handler-13:null) Done with process of VM state report. host: 27
> 2015-08-18 06:24:46,515 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentManager-Handler-13:null) Not processing PingRoutingCommand for agent
> id=0; can't find the host in the DB
> 2015-08-18 06:24:46,516 DEBUG [c.c.a.t.Request] (AgentManager-Handler-3:null)
> Seq 27-1186417026835415044: Processing: { Ans: , MgmtId: 279278805451086,
> via: 27, Ver: v1, Flags: 10,
> [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
> 2015-08-18 06:24:46,519 DEBUG [c.c.s.StorageManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Found storage pool ***.***.*** Local
> Storage of type Filesystem
> 2015-08-18 06:24:46,519 DEBUG [c.c.s.StorageManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Total over provisioned capacity of
> the pool ***.***.*** Local Storage id: 16 is 1563804868608
> 2015-08-18 06:24:46,522 DEBUG [c.c.s.StorageManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Successfully set Capacity -
> 1563804868608 for capacity type - 9 , DataCenterId - 6, HostOrPoolId - 16,
> PodId 7
> 2015-08-18 06:24:46,524 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Connect to listener:
> StorageCapacityListener
> 2015-08-18 06:24:46,524 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Connect to listener:
> ComputeCapacityListener
> 2015-08-18 06:24:46,532 DEBUG [c.c.c.CapacityManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Found 5 VMs on host 27
> 2015-08-18 06:24:46,542 DEBUG [c.c.c.CapacityManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Found 1 VM, not running on host 27
> 2015-08-18 06:24:46,544 ERROR [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Monitor ComputeCapacityListener says
> there is an error in the connect process for 27 due to null
> java.lang.NullPointerException
> 2015-08-18 06:24:46,544 INFO [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Host 27 is disconnecting with event
> AgentDisconnected
> 2015-08-18 06:24:46,545 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) The next status of agent 27is Alert,
> current status is Connecting
> 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Deregistering link for 27 with state
> Alert
> 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Remove Agent : 27
> 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.ConnectedAgentAttache]
> (AgentConnectTaskPool-213:ctx-76903ef6) Processing Disconnect.
> 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentAttache]
> (AgentConnectTaskPool-213:ctx-76903ef6) Seq 27-1186417026835415042: Sending
> disconnect to class com.cloud.network.security.SecurityGroupListener
> 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Disconnect to listener:
> com.cloud.hypervisor.xenserver.discoverer.XcpServerDiscoverer
> 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Disconnect to listener:
> com.cloud.hypervisor.hyperv.discoverer.HypervServerDiscoverer
> 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Disconnect to listener:
> com.cloud.vm.ClusteredVirtualMachineManagerImpl
> 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Disconnect to listener:
> org.apache.cloudstack.engine.orchestration.NetworkOrchestrator
> 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Disconnect to listener:
> com.cloud.network.security.SecurityGroupListener
> 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Disconnect to listener:
> com.cloud.storage.listener.StoragePoolMonitor
> 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Disconnect to listener:
> com.cloud.deploy.DeploymentPlanningManagerImpl
> 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Disconnect to listener:
> com.cloud.hypervisor.vmware.manager.VmwareManagerImpl
> 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Disconnect to listener:
> com.cloud.storage.secondary.SecondaryStorageListener
> 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Disconnect to listener:
> com.cloud.network.SshKeysDistriMonitor
> 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Disconnect to listener:
> com.cloud.network.router.VpcVirtualNetworkApplianceManagerImpl
> 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Disconnect to listener:
> com.cloud.agent.manager.AgentManagerImpl$BehindOnPingListener
> 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Disconnect to listener:
> com.cloud.storage.download.DownloadListener
> 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Disconnect to listener:
> com.cloud.network.SshKeysDistriMonitor
> 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Disconnect to listener:
> com.cloud.network.router.VirtualNetworkApplianceManagerImpl
> 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Disconnect to listener:
> com.cloud.network.NetworkUsageManagerImpl$DirectNetworkStatsListener
> 2015-08-18 06:24:46,546 DEBUG [c.c.n.NetworkUsageManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Disconnected called on 27 with status
> Alert
> 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Disconnect to listener:
> com.cloud.storage.upload.UploadListener
> 2015-08-18 06:24:46,546 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Disconnect to listener:
> com.cloud.consoleproxy.ConsoleProxyListener
> 2015-08-18 06:24:46,547 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Disconnect to listener:
> com.cloud.storage.LocalStoragePoolListener
> 2015-08-18 06:24:46,547 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Disconnect to listener:
> com.cloud.capacity.StorageCapacityListener
> 2015-08-18 06:24:46,547 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Sending Disconnect to listener:
> com.cloud.capacity.ComputeCapacityListener
> 2015-08-18 06:24:46,547 DEBUG [c.c.h.Status]
> (AgentConnectTaskPool-213:ctx-76903ef6) Transition:[Resource state = Enabled,
> Agent event = AgentDisconnected, Host id = 27, name = ***.***.***]
> 2015-08-18 06:24:46,551 DEBUG [c.c.a.m.ClusteredAgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Notifying other nodes of to disconnect
> 2015-08-18 06:24:46,554 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Failed to handle host connection:
> com.cloud.utils.exception.CloudRuntimeException: Unable to connect 27
> 2015-08-18 06:24:46,555 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentConnectTaskPool-213:ctx-76903ef6) Can not send command
> com.cloud.agent.api.ReadyCommand due to Host 27 is not up
> --- >8 ---
>
> Here's what I see on behalf of the agent:
>
> --- 8< ---
> 2015-08-18 06:24:46,199 INFO [cloud.agent.Agent] (Agent-Handler-3:null)
> Reconnecting...
> 2015-08-18 06:24:46,199 INFO [utils.nio.NioClient] (Agent-Selector:null)
> Connecting to ***.***.***.***:8250
> 2015-08-18 06:24:46,287 INFO [utils.nio.NioClient] (Agent-Selector:null)
> SSL: Handshake done
> 2015-08-18 06:24:46,287 INFO [utils.nio.NioClient] (Agent-Selector:null)
> Connected to ***.***.***.***:8250
> 2015-08-18 06:24:46,292 WARN [kvm.resource.LibvirtComputingResource]
> (Agent-Handler-1:null) Could not read cpuinfo_max_freq
> 2015-08-18 06:24:46,317 INFO [kvm.storage.LibvirtStorageAdaptor]
> (Agent-Handler-1:null) Attempting to create storage pool
> 51670fbd-ece2-4a3e-9971-3928e6576f0e (Filesystem) in libvirt
> 2015-08-18 06:24:46,332 INFO [cloud.agent.Agent] (Agent-Handler-2:null)
> Proccess agent startup answer, agent id = 0
> 2015-08-18 06:24:46,333 INFO [cloud.agent.Agent] (Agent-Handler-2:null) Set
> agent id 0
> 2015-08-18 06:24:46,333 INFO [cloud.agent.Agent] (Agent-Handler-2:null)
> Startup Response Received: agent id = 0
> 2015-08-18 06:24:46,555 WARN [cloud.agent.Agent] (Agent-Handler-5:null)
> Unable to send response: null
> 2015-08-18 06:24:51,288 INFO [cloud.agent.Agent] (Agent-Handler-3:null)
> Connected to the server
> 2015-08-18 06:24:51,546 INFO [cloud.agent.Agent] (Agent-Handler-4:null) Lost
> connection to the server. Dealing with the remaining commands...
> 2015-08-18 06:24:56,547 INFO [utils.nio.NioClient] (Agent-Handler-4:null)
> NioClient connection closed
> --- >8---
>
> Does anyone have an idea on what's wrong or how to get to know what's
> wrong? Thanks a lot!
>
> --
> V.Melnik
>
> P.S. It was working fine before we had upgraded from 4.4.2 to 4.5.1.
>
--
V.Melnik
