[
https://issues.apache.org/jira/browse/CLOUDSTACK-8747?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Vladimir Melnik updated CLOUDSTACK-8747:
----------------------------------------
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:
{code}
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
{code}
Here's what I see on behalf of the agent:
{code}
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
{code}
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.
was:
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:
{code}
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
{code}
Here's what I see on behalf of the agent:
{code}
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 comman
ds...
2015-08-18 06:24:56,547 INFO [utils.nio.NioClient] (Agent-Handler-4:null)
NioClient connection closed
{code}
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.
> The agent doesn't reconnect if there are stopped VMs
> ----------------------------------------------------
>
> Key: CLOUDSTACK-8747
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-8747
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the
> default.)
> Components: KVM
> Affects Versions: 4.5.1
> Environment: CentOS-6.6
> Reporter: Vladimir Melnik
> Priority: Critical
>
> 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:
> {code}
> 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
> {code}
> Here's what I see on behalf of the agent:
> {code}
> 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
> {code}
> 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.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
