Details
-
Bug
-
Status: Open
-
Critical
-
Resolution: Unresolved
-
4.5.1
-
None
-
Security Level: Public (Anyone can view this level - this is the default.)
-
None
-
CentOS-6.6
Description
I have a simple setup where the management server (CentOS-6.6 + ACS-4.5.1) is orchestrating a bunch of KVM hosts (CentOS-6.6 + ACS-4.5.1).
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:
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
Here's what I see on behalf of the agent:
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
Does anyone have an idea on what's wrong? Thanks a lot!
P.S. It was working fine before we had upgraded from 4.4.2 to 4.5.1.