[CLOUDSTACK-8747] The agent doesn't reconnect if there are stopped VMs - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Open
Priority: Critical
Resolution: Unresolved
Affects Version/s: 4.5.1
Fix Version/s: None
Component/s: KVM
Security Level: Public (Anyone can view this level - this is the default.)
Labels:
None
Environment:
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.

Attachments

Activity

People

Assignee:: Unassigned

Reporter:: Vladimir Melnik

Votes:: 0 Vote for this issue

Watchers:: 1 Start watching this issue

Dates

Created:: 18/Aug/15 15:03

Updated:: 09/Sep/15 05:54