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 <v.mel...@uplink.ua>
Sent: Thursday, August 20, 2015 4:36 AM
To: users@cloudstack.apache.org
Subject: The agent doesn't reconnect if there are stopped VMs
Dear colleagues,
I have a simple setup where the management server (CentOS-6.6 +
ACS-4.5.1) is orchestrating a bunch of KVM hosts (each of them is
running CentOS-6.6 + ACS-4.5.1 as well).
Any host with at least one VM in the "Stopped" state can't reconnect to
the management server. It has the "Alert" state and here's what I see in
the management server's log-file:
--- 8< ---
2015-08-18 06:24:46,332 DEBUG [c.c.a.t.Request]
(AgentConnectTaskPool-213:ctx-76903ef6) Seq 0-148: Processing the first command
{ Cmd ,
MgmtId: -1, via: 0, Ver: v1, Flags: 1,
[{"com.cloud.agent.api.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.
