Hello,
I have an issue and I do not understand where is the problem, it
worked before and now I get this error, so because of this all the KVM hosts
are in state connecting
is this a bug? I updated to cloudstack 4.13 1
month ago..
2020-05-28 08:00:09,462 DEBUG [kvm.resource.LibvirtComputingResource]
(UgentTask-2:null) (logid:) Executing:
/usr/share/cloudstack-common/scripts/vm/network/security_group.py
get_rule_logs_for_vms
2020-05-28 08:00:09,466 DEBUG [kvm.resource.LibvirtComputingResource]
(UgentTask-2:null) (logid:) Executing while with timeout : 1800000
2020-05-28 08:00:09,705 DEBUG [kvm.resource.LibvirtComputingResource]
(UgentTask-2:null) (logid:) Execution is successful.
2020-05-28 08:00:09,706 DEBUG [kvm.resource.LibvirtConnection]
(UgentTask-2:null) (logid:) Looking for libvirtd connection at:
qemu:///system
2020-05-28 08:00:09,755 DEBUG [cloud.agent.Agent] (UgentTask-2:null)
(logid:) Sending ping: Seq 0-2: { Cmd , MgmtId: -1, via: 0, Ver: v1, Flags:
11,
[{"com.cloud.agent.api.PingRoutingWithNwGroupsCommand":{"newGroupStates":{},
"_hostVmStateReport":{"i-169-1740-VM":{"state":"PowerOn","host":"kvm0201"},"
i-145-1541-VM":{"state":"PowerOn","host":"kvm0201"},"i-145-1529-VM":{"state"
:"PowerOn","host":"kvm0201"},"i-151-1641-VM":{"state":"PowerOn","host":"kvm0
201"},"i-129-1522-VM":{"state":"PowerOn","host":"kvm0201"}},"_gatewayAccessi
ble":true,"_vnetAccessible":true,"hostType":"Routing","hostId":0,"wait":0}}]
}
2020-05-28 08:00:09,797 DEBUG [cloud.agent.Agent] (Agent-Handler-5:null)
(logid:) Received response: Seq 0-2: { Ans: , MgmtId: 249302044940158, via:
98, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.PingAnswer":{"_command":{"hostType":"Routing","hostId
":0,"wait":0},"result":true,"wait":0}}] }
2020-05-28 08:01:00,958 ERROR [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-2:null) (logid:2c3479be) Failed to create RBD storage
pool: org.libvirt.LibvirtException: Konnte RBD-Image
'c47d7221-a664-41c6-a791-1148ec6f0850' nicht öffnen: Datei oder Verzeichnis
nicht gefunden
2020-05-28 08:01:00,959 ERROR [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-2:null) (logid:2c3479be) Failed to create the RBD
storage pool, cleaning up the libvirt secret
2020-05-28 08:01:00,964 WARN [cloud.agent.Agent]
(agentRequest-Handler-2:null) (logid:2c3479be) Caught:
com.cloud.utils.exception.CloudRuntimeException: Failed to create storage
pool: 2258aa76-7813-354d-b274-961fb337e716
at
com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.createStoragePool(Lib
virtStorageAdaptor.java:585)
at
com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.createStoragePool(KVM
StoragePoolManager.java:329)
at
com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.createStoragePool(KVM
StoragePoolManager.java:323)
at
com.cloud.hypervisor.kvm.resource.wrapper.LibvirtModifyStoragePoolCommandWra
pper.execute(LibvirtModifyStoragePoolCommandWrapper.java:42)
at
com.cloud.hypervisor.kvm.resource.wrapper.LibvirtModifyStoragePoolCommandWra
pper.execute(LibvirtModifyStoragePoolCommandWrapper.java:35)
at
com.cloud.hypervisor.kvm.resource.wrapper.LibvirtRequestWrapper.execute(Libv
irtRequestWrapper.java:78)
at
com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(Li
bvirtComputingResource.java:1476)
at com.cloud.agent.Agent.processRequest(Agent.java:640)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:1053)
at com.cloud.utils.nio.Task.call(Task.java:83)
at com.cloud.utils.nio.Task.call(Task.java:29)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:11
49)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:6
24)
at java.lang.Thread.run(Thread.java:748)
2020-05-28 08:01:00,968 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-2:null) (logid:2c3479be) Seq 98-8739235076912447489:
{ Ans: , MgmtId: 249302044940158, via: 98, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.Answer":{"result":false,"details":"com.cloud.utils.ex
ception.CloudRuntimeException: Failed to create storage pool:
2258aa76-7813-354d-b274-961fb337e716\n\tat
com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.createStoragePool(Lib
virtStorageAdaptor.java:585)\n\tat
com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.createStoragePool(KVM
StoragePoolManager.java:329)\n\tat
com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.createStoragePool(KVM
StoragePoolManager.java:323)\n\tat
com.cloud.hypervisor.kvm.resource.wrapper.LibvirtModifyStoragePoolCommandWra
pper.execute(LibvirtModifyStoragePoolCommandWrapper.java:42)\n\tat
com.cloud.hypervisor.kvm.resource.wrapper.LibvirtModifyStoragePoolCommandWra
pper.execute(LibvirtModifyStoragePoolCommandWrapper.java:35)\n\tat
com.cloud.hypervisor.kvm.resource.wrapper.LibvirtRequestWrapper.execute(Libv
irtRequestWrapper.java:78)\n\tat
com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(Li
bvirtComputingResource.java:1476)\n\tat
com.cloud.agent.Agent.processRequest(Agent.java:640)\n\tat
com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:1053)\n\tat
com.cloud.utils.nio.Task.call(Task.java:83)\n\tat
com.cloud.utils.nio.Task.call(Task.java:29)\n\tat
java.util.concurrent.FutureTask.run(FutureTask.java:266)\n\tat
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:11
49)\n\tat
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:6
24)\n\tat java.lang.Thread.run(Thread.java:748)\n","wait":0}}] }
2020-05-28 08:01:01,013 DEBUG [utils.nio.NioConnection]
(Agent-NioConnectionHandler-1:null) (logid:) Location 1: Socket
Socket[addr=/10.222.0.200,port=8251,localport=36436] closed on read.
Probably -1 returned: Connection closed with -1 on reading size.
2020-05-28 08:01:01,013 DEBUG [utils.nio.NioConnection]
(Agent-NioConnectionHandler-1:null) (logid:) Closing socket
Socket[addr=/10.222.0.200,port=8251,localport=36436]
2020-05-28 08:01:01,014 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
(logid:) Clearing watch list: 1
2020-05-28 08:01:01,014 INFO [cloud.agent.Agent] (Agent-Handler-1:null)
(logid:) Lost connection to host: 10.222.0.200. Attempting reconnection
while we still have 0 commands in progress.
2020-05-28 08:01:01,014 INFO [utils.nio.NioClient] (Agent-Handler-1:null)
(logid:) NioClient connection closed
2020-05-28 08:01:01,015 INFO [cloud.agent.Agent] (Agent-Handler-1:null)
(logid:) Reconnecting to host:10.222.0.200
2020-05-28 08:01:01,015 INFO [utils.nio.NioClient] (Agent-Handler-1:null)
(logid:) Connecting to 10.222.0.200:8251
2020-05-28 08:01:01,016 INFO [utils.nio.Link] (Agent-Handler-1:null)
(logid:) Conf file found: /etc/cloudstack/agent/agent.properties
2020-05-28 08:01:01,164 INFO [utils.nio.NioClient] (Agent-Handler-1:null)
(logid:) SSL: Handshake done
2020-05-28 08:01:01,164 INFO [utils.nio.NioClient] (Agent-Handler-1:null)
(logid:) Connected to 10.222.0.200:8251
2020-05-28 08:01:01,164 DEBUG [kvm.resource.LibvirtConnection]
(Agent-Handler-1:null) (logid:) Looking for libvirtd connection at:
qemu:///system
2020-05-28 08:01:01,215 DEBUG [kvm.resource.LibvirtCapXMLParser]
(Agent-Handler-1:null) (logid:) Found /usr/libexec/qemu-kvm as a suiteable
emulator
2020-05-28 08:01:01,218 DEBUG [cloud.resource.ServerResourceBase]
(Agent-Handler-1:null) (logid:) Parameters for private nic: 10.222.5.10 -
90:e2:ba:35:34:a0-255.255.252.0
2020-05-28 08:01:01,218 DEBUG [cloud.resource.ServerResourceBase]
(Agent-Handler-1:null) (logid:) Storage has its now nic: cloudbr249
2020-05-28 08:01:01,218 DEBUG [cloud.resource.ServerResourceBase]
(Agent-Handler-1:null) (logid:) Parameters for storage nic: 10.223.5.10 -
a0:36:9f:20:28:5c-255.255.0.0
2020-05-28 08:01:01,219 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) (logid:) Executing:
/usr/share/cloudstack-common/scripts/vm/hypervisor/versions.sh
2020-05-28 08:01:01,220 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) (logid:) Executing while with timeout : 1800000
2020-05-28 08:01:01,232 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) (logid:) Execution is successful.
2020-05-28 08:01:01,263 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) (logid:) Executing: sudo grep InitiatorName=
/etc/iscsi/initiatorname.iscsi
2020-05-28 08:01:01,264 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) (logid:) Executing while with timeout : 3600000
2020-05-28 08:01:01,303 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) (logid:) Execution is successful.
2020-05-28 08:01:01,305 INFO [kvm.storage.LibvirtStorageAdaptor]
(Agent-Handler-1:null) (logid:) Attempting to create storage pool
6fba7a90-a3e4-460b-9c21-b1c66ebbd1ad (Filesystem) in libvirt
2020-05-28 08:01:01,305 DEBUG [kvm.resource.LibvirtConnection]
(Agent-Handler-1:null) (logid:) Looking for libvirtd connection at:
qemu:///system
2020-05-28 08:01:01,306 ERROR [kvm.resource.LibvirtConnection]
(Agent-Handler-1:null) (logid:) Connection with libvirtd is broken:
ungültiger Verbindungszeiger in virConnectGetVersion
2020-05-28 08:01:01,306 DEBUG [kvm.resource.LibvirtConnection]
(Agent-Handler-1:null) (logid:) Opening a new libvirtd connection to:
qemu:///system
2020-05-28 08:01:01,323 INFO [kvm.storage.LibvirtStorageAdaptor]
(Agent-Handler-1:null) (logid:) Found existing defined storage pool
6fba7a90-a3e4-460b-9c21-b1c66ebbd1ad, using it.
2020-05-28 08:01:01,325 INFO [kvm.storage.LibvirtStorageAdaptor]
(Agent-Handler-1:null) (logid:) Trying to fetch storage pool
6fba7a90-a3e4-460b-9c21-b1c66ebbd1ad from libvirt
2020-05-28 08:01:01,325 DEBUG [kvm.resource.LibvirtConnection]
(Agent-Handler-1:null) (logid:) Looking for libvirtd connection at:
qemu:///system
2020-05-28 08:01:01,350 DEBUG [kvm.storage.LibvirtStorageAdaptor]
(Agent-Handler-1:null) (logid:) Succesfully refreshed pool
6fba7a90-a3e4-460b-9c21-b1c66ebbd1ad Capacity: 80491315200 Used: 3612864512
Available: 76878450688
2020-05-28 08:01:01,350 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
(logid:) Executing: hostname
2020-05-28 08:01:01,351 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
(logid:) Executing while with timeout : 500
2020-05-28 08:01:01,352 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
(logid:) Execution is successful.
2020-05-28 08:01:01,353 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
(logid:) Executing: hostname
2020-05-28 08:01:01,354 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
(logid:) Executing while with timeout : 500
2020-05-28 08:01:01,355 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
(logid:) Execution is successful.
2020-05-28 08:01:01,357 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
(logid:) Sending Startup: Seq 0-3: { Cmd , MgmtId: -1, via: 0, Ver: v1,
Flags: 1,
[{"com.cloud.agent.api.StartupRoutingCommand":{"cpuSockets":2,"cpus":16,"spe
ed":2395,"memory":66469244928,"dom0MinMemory":1073741824,"poolSync":false,"s
upportsClonedVolumes":false,"caps":"hvm,snapshot","pool":"/root","hypervisor
Type":"KVM","hostDetails":{"Host.OS.Kernel.Version":"4.17.13-1.el7.elrepo.x8
6_64","com.cloud.network.Networks.RouterPrivateIpStrategy":"HostLocal","Host
.OS.Version":"7.8.2003","secured":"true","Host.OS":"CentOS"},"hostTags":[],"
groupDetails":{},"type":"Routing","dataCenter":"2","pod":"2","cluster":"18",
"guid":"862603de-4865-3241-8055-e5bde9e25f6b-LibvirtComputingResource","name
":"kvm0201","id":0,"version":"4.13.0.0","iqn":"iqn.1994-05.com.redhat:b487e3
cd1fa2","privateIpAddress":"10.222.5.10","privateMacAddress":"90:e2:ba:35:34
:a0","privateNetmask":"255.255.252.0","storageIpAddress":"10.223.5.10","stor
ageNetmask":"255.255.0.0","storageMacAddress":"a0:36:9f:20:28:5c","resourceN
ame":"LibvirtComputingResource","gatewayIpAddress":"10.222.4.1","msHostList"
:"10.222.0.200@static","wait":0}},{"com.cloud.agent.api.StartupStorageComman
d":{"totalSize":0,"poolInfo":{"uuid":"6fba7a90-a3e4-460b-9c21-b1c66ebbd1ad",
"host":"10.222.5.10","localPath":"/var/lib/libvirt/images","hostPath":"/var/
lib/libvirt/images","poolType":"Filesystem","capacityBytes":80491315200,"ava
ilableBytes":76878450688},"resourceType":"STORAGE_POOL","hostDetails":{},"ty
pe":"Storage","dataCenter":"2","pod":"2","guid":"862603de-4865-3241-8055-e5b
de9e25f6b-LibvirtComputingResource","name":"kvm0201","id":0,"version":"4.13.
0.0","resourceName":"LibvirtComputingResource","msHostList":"10.222.0.200@st
atic","wait":0}}] }
2020-05-28 08:01:01,357 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
(logid:) Startup task created
2020-05-28 08:01:01,365 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null)
(logid:) Received response: Seq 0-3: { Ans: , MgmtId: 249302044940158, via:
-1, Ver: v1, Flags: 100000,
[{"com.cloud.agent.api.StartupAnswer":{"hostId":0,"pingInterval":60,"result"
:true,"wait":0}}] }
2020-05-28 08:01:01,366 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null)
(logid:) Startup task cancelled
2020-05-28 08:01:01,366 INFO [cloud.agent.Agent] (Agent-Handler-2:null)
(logid:) Proccess agent startup answer, agent id = 0
2020-05-28 08:01:01,366 INFO [cloud.agent.Agent] (Agent-Handler-2:null)
(logid:) Set agent id 0
2020-05-28 08:01:01,367 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null)
(logid:) Adding a watch list
2020-05-28 08:01:01,367 INFO [cloud.agent.Agent] (Agent-Handler-2:null)
(logid:) Startup Response Received: agent id = 0
2020-05-28 08:01:01,368 DEBUG [kvm.resource.LibvirtComputingResource]
(UgentTask-3:null) (logid:) Executing:
/usr/share/cloudstack-common/scripts/vm/network/security_group.py
get_rule_logs_for_vms
2020-05-28 08:01:01,369 DEBUG [kvm.resource.LibvirtComputingResource]
(UgentTask-3:null) (logid:) Executing while with timeout : 1800000
2020-05-28 08:01:01,538 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-3:null) (logid:545a28ec) Request:Seq
98-951385421282017281: { Cmd , MgmtId: 249302044940158, via: 98, Ver: v1,
Flags: 100011,
[{"com.cloud.agent.api.ModifyStoragePoolCommand":{"add":true,"pool":{"id":20
,"uuid":"2258aa76-7813-354d-b274-961fb337e716","host":"ceph-mon","path":"rbd
","userInfo":"admin:AQDWA1pbHMIfCBAAlO-Sl5U5QGHM_+nH3u7K7A==","port":6789,"t
ype":"RBD"},"localPath":"/mnt//9e8299eb-132c-3dc7-931e-a1591aacdf1a","wait":
0}}] }
2020-05-28 08:01:01,539 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-3:null) (logid:545a28ec) Processing command:
com.cloud.agent.api.ModifyStoragePoolCommand
2020-05-28 08:01:01,539 INFO [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-3:null) (logid:545a28ec) Attempting to create storage
pool 2258aa76-7813-354d-b274-961fb337e716 (RBD) in libvirt
2020-05-28 08:01:01,539 DEBUG [kvm.resource.LibvirtConnection]
(agentRequest-Handler-3:null) (logid:545a28ec) Looking for libvirtd
connection at: qemu:///system
2020-05-28 08:01:01,544 WARN [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-3:null) (logid:545a28ec) Storage pool
2258aa76-7813-354d-b274-961fb337e716 was not found running in libvirt. Need
to create it.
2020-05-28 08:01:01,544 INFO [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-3:null) (logid:545a28ec) Didn't find an existing
storage pool 2258aa76-7813-354d-b274-961fb337e716 by UUID, checking for
pools with duplicate paths
2020-05-28 08:01:01,550 DEBUG [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-3:null) (logid:545a28ec) Checking path of existing
pool b9a8ad4a-9032-3db2-ba98-938b891e1af1 against pool we want to create
2020-05-28 08:01:01,556 DEBUG [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-3:null) (logid:545a28ec) Checking path of existing
pool 31bf418a-be32-3a18-8c5d-c62eb4358eda against pool we want to create
2020-05-28 08:01:01,564 DEBUG [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-3:null) (logid:545a28ec) Checking path of existing
pool 6fba7a90-a3e4-460b-9c21-b1c66ebbd1ad against pool we want to create
2020-05-28 08:01:01,570 DEBUG [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-3:null) (logid:545a28ec) Attempting to create storage
pool 2258aa76-7813-354d-b274-961fb337e716
2020-05-28 08:01:01,570 DEBUG [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-3:null) (logid:545a28ec) <secret ephemeral='no'
private='no'>
<uuid>2258aa76-7813-354d-b274-961fb337e716</uuid>
<usage type='ceph'>
<name>admin@ceph-mon:6789/rbd</name>
</usage>
</secret>
2020-05-28 08:01:01,599 DEBUG [kvm.resource.LibvirtComputingResource]
(UgentTask-3:null) (logid:) Execution is successful.
2020-05-28 08:01:01,600 DEBUG [kvm.resource.LibvirtConnection]
(UgentTask-3:null) (logid:) Looking for libvirtd connection at:
qemu:///system
2020-05-28 08:01:01,608 DEBUG [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-3:null) (logid:545a28ec) <pool type='rbd'>
<name>2258aa76-7813-354d-b274-961fb337e716</name>
<uuid>2258aa76-7813-354d-b274-961fb337e716</uuid>
<source>
<host name='ceph-mon' port='6789'/>
<name>rbd</name>
<auth username='admin' type='ceph'>
<secret uuid='2258aa76-7813-354d-b274-961fb337e716'/>
</auth>
</source>
</pool>
2020-05-28 08:01:01,645 DEBUG [cloud.agent.Agent] (UgentTask-3:null)
(logid:) Sending ping: Seq 0-4: { Cmd , MgmtId: -1, via: 0, Ver: v1, Flags:
11,
[{"com.cloud.agent.api.PingRoutingWithNwGroupsCommand":{"newGroupStates":{},
"_hostVmStateReport":{"i-169-1740-VM":{"state":"PowerOn","host":"kvm0201"},"
i-145-1541-VM":{"state":"PowerOn","host":"kvm0201"},"i-145-1529-VM":{"state"
:"PowerOn","host":"kvm0201"},"i-151-1641-VM":{"state":"PowerOn","host":"kvm0
201"},"i-129-1522-VM":{"state":"PowerOn","host":"kvm0201"}},"_gatewayAccessi
ble":true,"_vnetAccessible":true,"hostType":"Routing","hostId":0,"wait":0}}]
}
2020-05-28 08:01:01,722 DEBUG [cloud.agent.Agent] (Agent-Handler-4:null)
(logid:) Received response: Seq 0-4: { Ans: , MgmtId: 249302044940158, via:
98, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.PingAnswer":{"_command":{"hostType":"Routing","hostId
":0,"wait":0},"result":true,"wait":0}}] }
2020-05-28 08:01:06,165 INFO [cloud.agent.Agent] (Agent-Handler-1:null)
(logid:) Connected to the host: 10.222.0.200
^C
[root@kvm0201 agent]# tail -f /var/log/cloudstack/agent/agent.log
<host name='ceph-mon' port='6789'/>
<name>rbd</name>
<auth username='admin' type='ceph'>
<secret uuid='2258aa76-7813-354d-b274-961fb337e716'/>
</auth>
</source>
</pool>
2020-05-28 08:04:01,724 DEBUG [cloud.agent.Agent] (Agent-Handler-4:null)
(logid:) Received response: Seq 0-11: { Ans: , MgmtId: 249302044940158,
via: 98, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.PingAnswer":{"_command":{"hostType":"Routing","hostId
":0,"wait":0},"result":true,"wait":0}}] }
2020-05-28 08:04:06,190 INFO [cloud.agent.Agent] (Agent-Handler-5:null)
(logid:) Connected to the host: 10.222.0.200
2020-05-28 08:04:56,355 ERROR [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-1:null) (logid:58052025) Failed to create RBD storage
pool: org.libvirt.LibvirtException: Konnte RBD-Image
'c47d7221-a664-41c6-a791-1148ec6f0850' nicht öffnen: Datei oder Verzeichnis
nicht gefunden
2020-05-28 08:04:56,355 ERROR [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-1:null) (logid:58052025) Failed to create the RBD
storage pool, cleaning up the libvirt secret
2020-05-28 08:04:56,358 WARN [cloud.agent.Agent]
(agentRequest-Handler-1:null) (logid:58052025) Caught:
com.cloud.utils.exception.CloudRuntimeException: Failed to create storage
pool: 2258aa76-7813-354d-b274-961fb337e716
at
com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.createStoragePool(Lib
virtStorageAdaptor.java:585)
at
com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.createStoragePool(KVM
StoragePoolManager.java:329)
at
com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.createStoragePool(KVM
StoragePoolManager.java:323)
at
com.cloud.hypervisor.kvm.resource.wrapper.LibvirtModifyStoragePoolCommandWra
pper.execute(LibvirtModifyStoragePoolCommandWrapper.java:42)
at
com.cloud.hypervisor.kvm.resource.wrapper.LibvirtModifyStoragePoolCommandWra
pper.execute(LibvirtModifyStoragePoolCommandWrapper.java:35)
at
com.cloud.hypervisor.kvm.resource.wrapper.LibvirtRequestWrapper.execute(Libv
irtRequestWrapper.java:78)
at
com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(Li
bvirtComputingResource.java:1476)
at com.cloud.agent.Agent.processRequest(Agent.java:640)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:1053)
at com.cloud.utils.nio.Task.call(Task.java:83)
at com.cloud.utils.nio.Task.call(Task.java:29)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:11
49)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:6
24)
at java.lang.Thread.run(Thread.java:748)
2020-05-28 08:04:56,359 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-1:null) (logid:58052025) Seq 98-9179180465511202817:
{ Ans: , MgmtId: 249302044940158, via: 98, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.Answer":{"result":false,"details":"com.cloud.utils.ex
ception.CloudRuntimeException: Failed to create storage pool:
2258aa76-7813-354d-b274-961fb337e716\n\tat
com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.createStoragePool(Lib
virtStorageAdaptor.java:585)\n\tat
com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.createStoragePool(KVM
StoragePoolManager.java:329)\n\tat
com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.createStoragePool(KVM
StoragePoolManager.java:323)\n\tat
com.cloud.hypervisor.kvm.resource.wrapper.LibvirtModifyStoragePoolCommandWra
pper.execute(LibvirtModifyStoragePoolCommandWrapper.java:42)\n\tat
com.cloud.hypervisor.kvm.resource.wrapper.LibvirtModifyStoragePoolCommandWra
pper.execute(LibvirtModifyStoragePoolCommandWrapper.java:35)\n\tat
com.cloud.hypervisor.kvm.resource.wrapper.LibvirtRequestWrapper.execute(Libv
irtRequestWrapper.java:78)\n\tat
com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(Li
bvirtComputingResource.java:1476)\n\tat
com.cloud.agent.Agent.processRequest(Agent.java:640)\n\tat
com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:1053)\n\tat
com.cloud.utils.nio.Task.call(Task.java:83)\n\tat
com.cloud.utils.nio.Task.call(Task.java:29)\n\tat
java.util.concurrent.FutureTask.run(FutureTask.java:266)\n\tat
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:11
49)\n\tat
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:6
24)\n\tat java.lang.Thread.run(Thread.java:748)\n","wait":0}}] }
2020-05-28 08:04:56,396 DEBUG [utils.nio.NioConnection]
(Agent-NioConnectionHandler-1:null) (logid:) Location 1: Socket
Socket[addr=/10.222.0.200,port=8251,localport=37508] closed on read.
Probably -1 returned: Connection closed with -1 on reading size.
2020-05-28 08:04:56,396 DEBUG [utils.nio.NioConnection]
(Agent-NioConnectionHandler-1:null) (logid:) Closing socket
Socket[addr=/10.222.0.200,port=8251,localport=37508]
2020-05-28 08:04:56,397 DEBUG [cloud.agent.Agent] (Agent-Handler-5:null)
(logid:) Clearing watch list: 1
2020-05-28 08:04:56,397 INFO [cloud.agent.Agent] (Agent-Handler-5:null)
(logid:) Lost connection to host: 10.222.0.200. Attempting reconnection
while we still have 0 commands in progress.
2020-05-28 08:04:56,399 INFO [utils.nio.NioClient] (Agent-Handler-5:null)
(logid:) NioClient connection closed
2020-05-28 08:04:56,399 INFO [cloud.agent.Agent] (Agent-Handler-5:null)
(logid:) Reconnecting to host:10.222.0.200
2020-05-28 08:04:56,399 INFO [utils.nio.NioClient] (Agent-Handler-5:null)
(logid:) Connecting to 10.222.0.200:8251
2020-05-28 08:04:56,401 INFO [utils.nio.Link] (Agent-Handler-5:null)
(logid:) Conf file found: /etc/cloudstack/agent/agent.properties
2020-05-28 08:04:56,510 INFO [utils.nio.NioClient] (Agent-Handler-5:null)
(logid:) SSL: Handshake done
2020-05-28 08:04:56,510 INFO [utils.nio.NioClient] (Agent-Handler-5:null)
(logid:) Connected to 10.222.0.200:8251
2020-05-28 08:04:56,511 DEBUG [kvm.resource.LibvirtConnection]
(Agent-Handler-1:null) (logid:) Looking for libvirtd connection at:
qemu:///system
2020-05-28 08:04:56,561 DEBUG [kvm.resource.LibvirtCapXMLParser]
(Agent-Handler-1:null) (logid:) Found /usr/libexec/qemu-kvm as a suiteable
emulator
2020-05-28 08:04:56,564 DEBUG [cloud.resource.ServerResourceBase]
(Agent-Handler-1:null) (logid:) Parameters for private nic: 10.222.5.10 -
90:e2:ba:35:34:a0-255.255.252.0
2020-05-28 08:04:56,564 DEBUG [cloud.resource.ServerResourceBase]
(Agent-Handler-1:null) (logid:) Storage has its now nic: cloudbr249
2020-05-28 08:04:56,564 DEBUG [cloud.resource.ServerResourceBase]
(Agent-Handler-1:null) (logid:) Parameters for storage nic: 10.223.5.10 -
a0:36:9f:20:28:5c-255.255.0.0
2020-05-28 08:04:56,564 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) (logid:) Executing:
/usr/share/cloudstack-common/scripts/vm/hypervisor/versions.sh
2020-05-28 08:04:56,565 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) (logid:) Executing while with timeout : 1800000
2020-05-28 08:04:56,582 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) (logid:) Execution is successful.
2020-05-28 08:04:56,617 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) (logid:) Executing: sudo grep InitiatorName=
/etc/iscsi/initiatorname.iscsi
2020-05-28 08:04:56,618 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) (logid:) Executing while with timeout : 3600000
2020-05-28 08:04:56,662 DEBUG [kvm.resource.LibvirtComputingResource]
(Agent-Handler-1:null) (logid:) Execution is successful.
2020-05-28 08:04:56,663 INFO [kvm.storage.LibvirtStorageAdaptor]
(Agent-Handler-1:null) (logid:) Attempting to create storage pool
6fba7a90-a3e4-460b-9c21-b1c66ebbd1ad (Filesystem) in libvirt
2020-05-28 08:04:56,663 DEBUG [kvm.resource.LibvirtConnection]
(Agent-Handler-1:null) (logid:) Looking for libvirtd connection at:
qemu:///system
2020-05-28 08:04:56,665 ERROR [kvm.resource.LibvirtConnection]
(Agent-Handler-1:null) (logid:) Connection with libvirtd is broken:
ungültiger Verbindungszeiger in virConnectGetVersion
2020-05-28 08:04:56,665 DEBUG [kvm.resource.LibvirtConnection]
(Agent-Handler-1:null) (logid:) Opening a new libvirtd connection to:
qemu:///system
2020-05-28 08:04:56,682 INFO [kvm.storage.LibvirtStorageAdaptor]
(Agent-Handler-1:null) (logid:) Found existing defined storage pool
6fba7a90-a3e4-460b-9c21-b1c66ebbd1ad, using it.
2020-05-28 08:04:56,684 INFO [kvm.storage.LibvirtStorageAdaptor]
(Agent-Handler-1:null) (logid:) Trying to fetch storage pool
6fba7a90-a3e4-460b-9c21-b1c66ebbd1ad from libvirt
2020-05-28 08:04:56,684 DEBUG [kvm.resource.LibvirtConnection]
(Agent-Handler-1:null) (logid:) Looking for libvirtd connection at:
qemu:///system
2020-05-28 08:04:56,710 DEBUG [kvm.storage.LibvirtStorageAdaptor]
(Agent-Handler-1:null) (logid:) Succesfully refreshed pool
6fba7a90-a3e4-460b-9c21-b1c66ebbd1ad Capacity: 80491315200 Used: 3612864512
Available: 76878450688
2020-05-28 08:04:56,710 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
(logid:) Executing: hostname
2020-05-28 08:04:56,712 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
(logid:) Executing while with timeout : 500
2020-05-28 08:04:56,712 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
(logid:) Execution is successful.
2020-05-28 08:04:56,714 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
(logid:) Executing: hostname
2020-05-28 08:04:56,715 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
(logid:) Executing while with timeout : 500
2020-05-28 08:04:56,716 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
(logid:) Execution is successful.
2020-05-28 08:04:56,719 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
(logid:) Sending Startup: Seq 0-12: { Cmd , MgmtId: -1, via: 0, Ver: v1,
Flags: 1,
[{"com.cloud.agent.api.StartupRoutingCommand":{"cpuSockets":2,"cpus":16,"spe
ed":2395,"memory":66469244928,"dom0MinMemory":1073741824,"poolSync":false,"s
upportsClonedVolumes":false,"caps":"hvm,snapshot","pool":"/root","hypervisor
Type":"KVM","hostDetails":{"Host.OS.Kernel.Version":"4.17.13-1.el7.elrepo.x8
6_64","com.cloud.network.Networks.RouterPrivateIpStrategy":"HostLocal","Host
.OS.Version":"7.8.2003","secured":"true","Host.OS":"CentOS"},"hostTags":[],"
groupDetails":{},"type":"Routing","dataCenter":"2","pod":"2","cluster":"18",
"guid":"862603de-4865-3241-8055-e5bde9e25f6b-LibvirtComputingResource","name
":"kvm0201","id":0,"version":"4.13.0.0","iqn":"iqn.1994-05.com.redhat:b487e3
cd1fa2","privateIpAddress":"10.222.5.10","privateMacAddress":"90:e2:ba:35:34
:a0","privateNetmask":"255.255.252.0","storageIpAddress":"10.223.5.10","stor
ageNetmask":"255.255.0.0","storageMacAddress":"a0:36:9f:20:28:5c","resourceN
ame":"LibvirtComputingResource","gatewayIpAddress":"10.222.4.1","msHostList"
:"10.222.0.200@static","wait":0}},{"com.cloud.agent.api.StartupStorageComman
d":{"totalSize":0,"poolInfo":{"uuid":"6fba7a90-a3e4-460b-9c21-b1c66ebbd1ad",
"host":"10.222.5.10","localPath":"/var/lib/libvirt/images","hostPath":"/var/
lib/libvirt/images","poolType":"Filesystem","capacityBytes":80491315200,"ava
ilableBytes":76878450688},"resourceType":"STORAGE_POOL","hostDetails":{},"ty
pe":"Storage","dataCenter":"2","pod":"2","guid":"862603de-4865-3241-8055-e5b
de9e25f6b-LibvirtComputingResource","name":"kvm0201","id":0,"version":"4.13.
0.0","resourceName":"LibvirtComputingResource","msHostList":"10.222.0.200@st
atic","wait":0}}] }
2020-05-28 08:04:56,719 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null)
(logid:) Startup task created
2020-05-28 08:04:56,728 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null)
(logid:) Received response: Seq 0-12: { Ans: , MgmtId: 249302044940158,
via: -1, Ver: v1, Flags: 100000,
[{"com.cloud.agent.api.StartupAnswer":{"hostId":0,"pingInterval":60,"result"
:true,"wait":0}}] }
2020-05-28 08:04:56,729 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null)
(logid:) Startup task cancelled
2020-05-28 08:04:56,729 INFO [cloud.agent.Agent] (Agent-Handler-2:null)
(logid:) Proccess agent startup answer, agent id = 0
2020-05-28 08:04:56,729 INFO [cloud.agent.Agent] (Agent-Handler-2:null)
(logid:) Set agent id 0
2020-05-28 08:04:56,729 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null)
(logid:) Adding a watch list
2020-05-28 08:04:56,730 INFO [cloud.agent.Agent] (Agent-Handler-2:null)
(logid:) Startup Response Received: agent id = 0
2020-05-28 08:04:56,730 DEBUG [kvm.resource.LibvirtComputingResource]
(UgentTask-5:null) (logid:) Executing:
/usr/share/cloudstack-common/scripts/vm/network/security_group.py
get_rule_logs_for_vms
2020-05-28 08:04:56,731 DEBUG [kvm.resource.LibvirtComputingResource]
(UgentTask-5:null) (logid:) Executing while with timeout : 1800000
2020-05-28 08:04:56,899 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-2:null) (logid:7bf307a5) Request:Seq
98-8704050704823615489: { Cmd , MgmtId: 249302044940158, via: 98, Ver: v1,
Flags: 100011,
[{"com.cloud.agent.api.ModifyStoragePoolCommand":{"add":true,"pool":{"id":20
,"uuid":"2258aa76-7813-354d-b274-961fb337e716","host":"ceph-mon","path":"rbd
","userInfo":"admin:AQDWA1pbHMIfCBAAlO-Sl5U5QGHM_+nH3u7K7A==","port":6789,"t
ype":"RBD"},"localPath":"/mnt//9e8299eb-132c-3dc7-931e-a1591aacdf1a","wait":
0}}] }
2020-05-28 08:04:56,899 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-2:null) (logid:7bf307a5) Processing command:
com.cloud.agent.api.ModifyStoragePoolCommand
2020-05-28 08:04:56,899 INFO [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-2:null) (logid:7bf307a5) Attempting to create storage
pool 2258aa76-7813-354d-b274-961fb337e716 (RBD) in libvirt
2020-05-28 08:04:56,899 DEBUG [kvm.resource.LibvirtConnection]
(agentRequest-Handler-2:null) (logid:7bf307a5) Looking for libvirtd
connection at: qemu:///system
2020-05-28 08:04:56,903 WARN [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-2:null) (logid:7bf307a5) Storage pool
2258aa76-7813-354d-b274-961fb337e716 was not found running in libvirt. Need
to create it.
2020-05-28 08:04:56,903 INFO [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-2:null) (logid:7bf307a5) Didn't find an existing
storage pool 2258aa76-7813-354d-b274-961fb337e716 by UUID, checking for
pools with duplicate paths
2020-05-28 08:04:56,909 DEBUG [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-2:null) (logid:7bf307a5) Checking path of existing
pool b9a8ad4a-9032-3db2-ba98-938b891e1af1 against pool we want to create
2020-05-28 08:04:56,915 DEBUG [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-2:null) (logid:7bf307a5) Checking path of existing
pool 31bf418a-be32-3a18-8c5d-c62eb4358eda against pool we want to create
2020-05-28 08:04:56,921 DEBUG [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-2:null) (logid:7bf307a5) Checking path of existing
pool 6fba7a90-a3e4-460b-9c21-b1c66ebbd1ad against pool we want to create
2020-05-28 08:04:56,927 DEBUG [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-2:null) (logid:7bf307a5) Attempting to create storage
pool 2258aa76-7813-354d-b274-961fb337e716
2020-05-28 08:04:56,927 DEBUG [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-2:null) (logid:7bf307a5) <secret ephemeral='no'
private='no'>
<uuid>2258aa76-7813-354d-b274-961fb337e716</uuid>
<usage type='ceph'>
<name>admin@ceph-mon:6789/rbd</name>
</usage>
</secret>
2020-05-28 08:04:56,955 DEBUG [kvm.resource.LibvirtComputingResource]
(UgentTask-5:null) (logid:) Execution is successful.
2020-05-28 08:04:56,956 DEBUG [kvm.resource.LibvirtConnection]
(UgentTask-5:null) (logid:) Looking for libvirtd connection at:
qemu:///system
2020-05-28 08:04:56,960 DEBUG [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-2:null) (logid:7bf307a5) <pool type='rbd'>
<name>2258aa76-7813-354d-b274-961fb337e716</name>
<uuid>2258aa76-7813-354d-b274-961fb337e716</uuid>
<source>
<host name='ceph-mon' port='6789'/>
<name>rbd</name>
<auth username='admin' type='ceph'>
<secret uuid='2258aa76-7813-354d-b274-961fb337e716'/>
</auth>
</source>
</pool>
2020-05-28 08:04:56,990 DEBUG [cloud.agent.Agent] (UgentTask-5:null)
(logid:) Sending ping: Seq 0-13: { Cmd , MgmtId: -1, via: 0, Ver: v1,
Flags: 11,
[{"com.cloud.agent.api.PingRoutingWithNwGroupsCommand":{"newGroupStates":{},
"_hostVmStateReport":{"i-169-1740-VM":{"state":"PowerOn","host":"kvm0201"},"
i-145-1541-VM":{"state":"PowerOn","host":"kvm0201"},"i-145-1529-VM":{"state"
:"PowerOn","host":"kvm0201"},"i-151-1641-VM":{"state":"PowerOn","host":"kvm0
201"},"i-129-1522-VM":{"state":"PowerOn","host":"kvm0201"}},"_gatewayAccessi
ble":true,"_vnetAccessible":true,"hostType":"Routing","hostId":0,"wait":0}}]
}
2020-05-28 08:04:57,062 DEBUG [cloud.agent.Agent] (Agent-Handler-4:null)
(logid:) Received response: Seq 0-13: { Ans: , MgmtId: 249302044940158,
via: 98, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.PingAnswer":{"_command":{"hostType":"Routing","hostId
":0,"wait":0},"result":true,"wait":0}}] }
2020-05-28 08:05:01,511 INFO [cloud.agent.Agent] (Agent-Handler-5:null)
(logid:) Connected to the host: 10.222.0.200
Thank you in advance,
Cristian
