Hi guys,
I had managemetn server stoped for some time, started again - but after
that one of the agents can not connect.
I have enabled debug loging on agent:
Any help would be very appriciated...
2014-10-31 12:05:16,764 INFO [utils.nio.NioClient] (Agent-Selector:null)
Connecting to 10.0.0.1:8250
2014-10-31 12:05:16,851 INFO [utils.nio.NioClient] (Agent-Selector:null)
SSL: Handshake done
2014-10-31 12:05:16,851 INFO [utils.nio.NioClient] (Agent-Selector:null)
Connected to 10.0.0.1:8250
2014-10-31 12:05:16,857 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) Detecting a new state but couldn't find a old state
so adding it to the changes: i-3-41-VM
2014-10-31 12:05:16,857 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) Detecting a new state but couldn't find a old state
so adding it to the changes: i-3-39-VM
2014-10-31 12:05:16,857 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) Detecting a new state but couldn't find a old state
so adding it to the changes: i-3-40-VM
2014-10-31 12:05:16,857 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) Detecting a new state but couldn't find a old state
so adding it to the changes: s-28-VM
2014-10-31 12:05:16,872 DEBUG [kvm.resource.LibvirtCapXMLParser]
(Agent-Handler-1:null) Found /usr/libexec/qemu-kvm as a suiteable emulator
2014-10-31 12:05:16,872 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) Executing: /bin/bash -c qemu-img --help|grep convert
2014-10-31 12:05:16,876 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) Execution is successful.
2014-10-31 12:05:16,876 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) convert [-c] [-p] [-f fmt] [-t cache] [-O
output_fmt] [-o options] [-S sparse_size] filename [filename2 [...]]
output_filename
2014-10-31 12:05:16,876 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) cpus=32, speed=3400, ram=271057920000,
dom0ram=805306368, cpu sockets=1
2014-10-31 12:05:16,877 DEBUG [cloud.resource.ServerResourceBase]
(Agent-Handler-1:null) Parameters for private nic: 10.0.5.18 -
c4:54:44:1e:35:af-255.255.255.0
2014-10-31 12:05:16,877 DEBUG [cloud.resource.ServerResourceBase]
(Agent-Handler-1:null) Parameters for storage nic: 10.0.5.18 -
c4:54:44:1e:35:af-255.255.255.0
2014-10-31 12:05:16,877 DEBUG [cloud.resource.ServerResourceBase]
(Agent-Handler-1:null) Parameters for pubic nic: 10.0.5.18 -
c4:54:44:1e:35:af-255.255.255.0
2014-10-31 12:05:16,877 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) Executing:
/usr/share/cloudstack-common/scripts/vm/hypervisor/versions.sh
2014-10-31 12:05:16,885 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) Execution is successful.
2014-10-31 12:05:16,892 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) Executing: sudo grep InitiatorName=
/etc/iscsi/initiatorname.iscsi
2014-10-31 12:05:16,896 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) Exit value is 1
2014-10-31 12:05:16,896 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) sudo: sorry, you must have a tty to run sudo
2014-10-31 12:05:16,897 DEBUG [kvm.storage.LibvirtStorageAdaptor]
(Agent-Handler-1:null) Found existing defined storage pool
234cb38b-afef-4554-a356-8c4f08fa7875, using it.
2014-10-31 12:05:16,901 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
Executing: hostname
2014-10-31 12:05:16,902 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
Execution is successful.
2014-10-31 12:05:16,902 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
Executing: hostname
2014-10-31 12:05:16,903 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
Execution is successful.
2014-10-31 12:05:16,905 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
Sending Startup: Seq 0-56: { Cmd , MgmtId: -1, via: 0, Ver: v1, Flags: 1,
[{"com.cloud.agent.api.StartupRoutingCommand":{"cpuSockets":1,"cpus":32,"speed":3400,"memory":271057920000,"dom0MinMemory":805306368,"poolSync":false,"_hostVmStateReport":{"i-3-41-VM":{"state":"PowerOn","host":"compute5.localdomain"},"i-3-39-VM":{"state":"PowerOn","host":"compute5.localdomain"},"i-3-40-VM":{"state":"PowerOn","host":"compute5.localdomain"},"s-28-VM":{"state":"PowerOn","host":"compute5.localdomain"}},"vms":{"i-3-41-VM":{"state":"Running"},"i-3-39-VM":{"state":"Running"},"i-3-40-VM":{"state":"Running"},"s-28-VM":{"state":"Running"}},"caps":"hvm,snapshot","pool":"/root","hypervisorType":"KVM","hostDetails":{"com.cloud.network.Networks.RouterPrivateIpStrategy":"HostLocal","Host.OS":"CentOS","Host.OS.Kernel.Version":"3.10.58-1.el6.elrepo.x86_64","Host.OS.Version":"6.5"},"groupDetails":{},"type":"Routing","dataCenter":"1","pod":"1","cluster":"1","guid":"1aea3476-8742-3090-851d-b8e6f9ba3c09-LibvirtComputingResource","name":"compute5.localdomain","id":0,"version":"4.4.1","publicIpAddress":"10.0.5.18","publicNetmask":"255.255.255.0","publicMacAddress":"c4:54:44:1e:35:af","privateIpAddress":"10.0.5.18","privateMacAddress":"c4:54:44:1e:35:af","privateNetmask":"255.255.255.0","storageIpAddress":"10.0.5.18","storageNetmask":"255.255.255.0","storageMacAddress":"c4:54:44:1e:35:af","resourceName":"LibvirtComputingResource","gatewayIpAddress":"10.0.0.11","wait":0}},{"com.cloud.agent.api.StartupStorageCommand":{"totalSize":0,"poolInfo":{"uuid":"234cb38b-afef-4554-a356-8c4f08fa7875","host":"10.0.5.18","localPath":"/var/lib/libvirt/images","hostPath":"/var/lib/libvirt/images","poolType":"Filesystem","capacityBytes":5684924784640,"availableBytes":3829623398400},"resourceType":"STORAGE_POOL","hostDetails":{},"type":"Storage","dataCenter":"1","pod":"1","guid":"1aea3476-8742-3090-851d-b8e6f9ba3c09-LibvirtComputingResource","name":"compute5.localdomain","id":0,"version":"4.4.1","resourceName":"LibvirtComputingResource","wait":0}}]
}
2014-10-31 12:05:16,905 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
Startup task created
2014-10-31 12:05:16,909 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null)
Received response: Seq 0-56: { Ans: , MgmtId: 90327514945724, via: -1,
Ver: v1, Flags: 100000,
[{"com.cloud.agent.api.StartupAnswer":{"hostId":0,"pingInterval":60,"result":true,"wait":0}}]
}
2014-10-31 12:05:16,909 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null)
Startup task cancelled
2014-10-31 12:05:16,909 INFO [cloud.agent.Agent] (Agent-Handler-2:null)
Proccess agent startup answer, agent id = 0
2014-10-31 12:05:16,909 INFO [cloud.agent.Agent] (Agent-Handler-2:null)
Set agent id 0
2014-10-31 12:05:16,910 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null)
Adding a watch list
2014-10-31 12:05:16,910 INFO [cloud.agent.Agent] (Agent-Handler-2:null)
Startup Response Received: agent id = 0
2014-10-31 12:05:16,915 DEBUG [kvm.resource.LibvirtComputingResource]
(UgentTask-5:null) Executing:
/usr/share/cloudstack-common/scripts/vm/network/security_group.py
get_rule_logs_for_vms
2014-10-31 12:05:16,930 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-3:null) Request:Seq 2-1953436338371952641: { Cmd ,
MgmtId: 90327514945724, via: 2, Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.CheckNetworkCommand":{"networkInfoList":[{"physicalNetworkId":200,"storageNetworkName":"cloudbr2"},{"physicalNetworkId":201,"privateNetworkName":"cloudbr0","publicNetworkName":"cloudbr0"},{"physicalNetworkId":202,"guestNetworkName":"eth3"}],"wait":0}}]
}
2014-10-31 12:05:16,930 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-3:null) Processing command:
com.cloud.agent.api.CheckNetworkCommand
2014-10-31 12:05:16,930 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-3:null) matchPifFileInDirectory: file name 'eth0'
2014-10-31 12:05:16,930 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-3:null) matchPifFileInDirectory: file name 'eth0'
2014-10-31 12:05:16,931 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-3:null) Seq 2-1953436338371952641: { Ans: , MgmtId:
90327514945724, via: 2, Ver: v1, Flags: 110,
[{"com.cloud.agent.api.CheckNetworkAnswer":{"_reconnect":false,"result":true,"wait":0}}]
}
2014-10-31 12:05:16,985 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-4:null) Request:Seq 2-1953436338371952642: { Cmd ,
MgmtId: 90327514945724, via: 2, Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.CleanupNetworkRulesCmd":{"interval":2100,"wait":0}}]
}
2014-10-31 12:05:16,985 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-4:null) Processing command:
com.cloud.agent.api.CleanupNetworkRulesCmd
2014-10-31 12:05:16,985 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-4:null) Adding a watch list
2014-10-31 12:05:16,985 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) Executing:
/usr/share/cloudstack-common/scripts/vm/network/security_group.py
cleanup_rules
2014-10-31 12:05:16,985 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-5:null) Request:Seq 2-1953436338371952643: { Cmd ,
MgmtId: 90327514945724, via: 2, Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.ModifySshKeysCommand":{"wait":0}}] }
2014-10-31 12:05:16,985 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-4:null) Seq 2-1953436338371952642: { Ans: , MgmtId:
90327514945724, via: 2, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2014-10-31 12:05:16,985 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-5:null) Processing command:
com.cloud.agent.api.ModifySshKeysCommand
2014-10-31 12:05:16,985 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-5:null) Executing: chmod 600 /root/.ssh/id_rsa.cloud
2014-10-31 12:05:16,986 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-5:null) Execution is successful.
2014-10-31 12:05:16,987 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-5:null) Seq 2-1953436338371952643: { Ans: , MgmtId:
90327514945724, via: 2, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2014-10-31 12:05:16,988 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-1:null) Request:Seq 2-1953436338371952644: { Cmd ,
MgmtId: 90327514945724, via: 2, Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.ModifySshKeysCommand":{"wait":0}}] }
2014-10-31 12:05:16,988 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-1:null) Processing command:
com.cloud.agent.api.ModifySshKeysCommand
2014-10-31 12:05:16,989 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-1:null) Executing: chmod 600 /root/.ssh/id_rsa.cloud
2014-10-31 12:05:16,990 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-1:null) Execution is successful.
2014-10-31 12:05:16,990 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-1:null) Seq 2-1953436338371952644: { Ans: , MgmtId:
90327514945724, via: 2, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2014-10-31 12:05:16,997 DEBUG [utils.nio.NioConnection]
(Agent-Selector:null) Location 1: Socket
Socket[addr=/10.0.0.1,port=8250,localport=34618]
closed on read. Probably -1 returned: Connection closed with -1 on reading
size.
2014-10-31 12:05:16,998 DEBUG [utils.nio.NioConnection]
(Agent-Selector:null) Closing socket Socket[addr=/10.0.0.1
,port=8250,localport=34618]
2014-10-31 12:05:16,998 DEBUG [cloud.agent.Agent] (Agent-Handler-3:null)
Clearing watch list: 2
2014-10-31 12:05:16,998 DEBUG [kvm.resource.LibvirtComputingResource]
(UgentTask-5:null) Execution is successful.
2014-10-31 12:05:17,005 DEBUG [cloud.agent.Agent] (UgentTask-5:null)
Sending ping: Seq 0-57: { Cmd , MgmtId: -1, via: 0, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.PingRoutingWithNwGroupsCommand":{"newGroupStates":{},"newStates":{},"_hostVmStateReport":{"i-3-41-VM":{"state":"PowerOn","host":"compute5.localdomain"},"i-3-39-VM":{"state":"PowerOn","host":"compute5.localdomain"},"i-3-40-VM":{"state":"PowerOn","host":"compute5.localdomain"},"s-28-VM":{"state":"PowerOn","host":"compute5.localdomain"}},"_gatewayAccessible":true,"_vnetAccessible":true,"hostType":"Routing","hostId":0,"wait":0}}]
}
2014-10-31 12:05:17,007 WARN [cloud.agent.Agent] (UgentTask-5:null) Unable
to send request: Seq 0-57: { Cmd , MgmtId: -1, via: 0, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.PingRoutingWithNwGroupsCommand":{"newGroupStates":{},"newStates":{},"_hostVmStateReport":{"i-3-41-VM":{"state":"PowerOn","host":"compute5.localdomain"},"i-3-39-VM":{"state":"PowerOn","host":"compute5.localdomain"},"i-3-40-VM":{"state":"PowerOn","host":"compute5.localdomain"},"s-28-VM":{"state":"PowerOn","host":"compute5.localdomain"}},"_gatewayAccessible":true,"_vnetAccessible":true,"hostType":"Routing","hostId":0,"wait":0}}]
}
2014-10-31 12:05:17,056 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) Execution is successful.
2014-10-31 12:05:17,056 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
Watch Sent: Seq 2-1953436338371952642: { Ans: , MgmtId: 90327514945724,
via: 2, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.Answer":{"result":true,"details":"","wait":0}}] }
2014-10-31 12:05:17,057 WARN [cloud.agent.Agent] (Agent-Handler-1:null)
Unable to send response: Seq 2-1953436338371952642: { Ans: , MgmtId:
90327514945724, via: 2, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.Answer":{"result":true,"details":"","wait":0}}] }
2014-10-31 12:05:21,851 INFO [cloud.agent.Agent] (Agent-Handler-3:null)
Connected to the server
2014-10-31 12:05:21,998 INFO [cloud.agent.Agent] (Agent-Handler-3:null)
Lost connection to the server. Dealing with the remaining commands...
--
Andrija Panić
--------------------------------------
http://admintweets.com
--------------------------------------
