Ceph RBD primary storage fails connection and renders node unusable

[giorgiomassar8]

ISSUE TYPE

• Bug Report

COMPONENT NAME

Cloudstack agent

CLOUDSTACK VERSION

4.11

CONFIGURATION

KVM cluster with CEPH backed RDB primary storage

OS / ENVIRONMENT

Ubuntu 16.04 / 14.04

SUMMARY

On a perfectly working 4.10 node with KVM hypervisor and Ceph RBD primary storage, after upgrading to 4.11, cloudstack agent is unable to connect the BRD pool in libvirt, giving just a generic "operation not supported" error in its logs:

2018-04-06 16:27:37,650 INFO [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:91b4e1df) Attempting to create storage pool be80af6a-7201-3410-8da4-9b3b58c4954f (RBD) in libvirt
2018-04-06 16:27:37,652 WARN [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:91b4e1df) Storage pool be80af6a-7201-3410-8da4-9b3b58c4954f was not found running in libvirt. Need to create it.
2018-04-06 16:27:37,653 INFO [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:91b4e1df) Didn't find an existing storage pool be80af6a-7201-3410-8da4-9b3b58c4954f by UUID, checking for pools with duplicate paths
2018-04-06 16:27:37,664 ERROR [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:91b4e1df) Failed to create RBD storage pool: org.libvirt.LibvirtException: failed to connect to the RADOS monitor on: storagepool1:6789,: Operation not supported
2018-04-06 16:27:42,762 INFO [cloud.agent.Agent] (Agent-Handler-4:null) (logid Lost connection to the server. Dealing with the remaining commands...

Exactly the same pool was previously working before upgrade:

2018-04-06 12:53:52,847 INFO [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:14dace5e) Attempting to create storage pool be80af6a-7201-3410-8da4-9b3b58c4954f (RBD) in libvirt
2018-04-06 12:53:52,850 INFO [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:14dace5e) Found existing defined storage pool be80af6a-7201-3410-8da4-9b3b58c4954f, using it.
2018-04-06 12:53:52,850 INFO [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:14dace5e) Trying to fetch storage pool be80af6a-7201-3410-8da4-9b3b58c4954f from libvirt
2018-04-06 12:53:53,171 INFO [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:14dace5e) Proccess agent ready command, agent id = 46

STEPS TO REPRODUCE

Take an existing and working cloudstack cluster with 4.10, with RDB primary storage and Ubuntu 14.04 based agents and upgrade them to version 4.11 of the agent.

EXPECTED RESULTS

The cluster should be working fine, the agents should be connecting and the RDB pool should be correctly opened in libvirt.

ACTUAL RESULTS

Cloudstack agents fails to boot with a generic "Failed to create RBD storage pool: org.libvirt.LibvirtException: failed to connect to the RADOS monitor on: storagepool1:6789,: Operation not supported" error and loops in a failed state, rendering the machine unusable.

WORKAROUND

To workaround the issue I have tried to use the following XML config (dumped from another node where it is correctly running) and define the pool directly in libvirt, and it worked as expected:

be80af6a-7201-3410-8da4-9b3b58c4954f be80af6a-7201-3410-8da4-9b3b58c4954f cephstor1

virsh pool-define test.xml
Pool be80af6a-7201-3410-8da4-9b3b58c4954f defined from test.xml

root@compute6:~# virsh pool-start be80af6a-7201-3410-8da4-9b3b58c4954f
Pool be80af6a-7201-3410-8da4-9b3b58c4954f started

root@compute6:~# virsh pool-info be80af6a-7201-3410-8da4-9b3b58c4954f
Name: be80af6a-7201-3410-8da4-9b3b58c4954f
UUID: be80af6a-7201-3410-8da4-9b3b58c4954f
State: running
Persistent: yes
Autostart: no
Capacity: 10.05 TiB
Allocation: 2.22 TiB
Available: 2.71 TiB

And now the cloudstack agent correctly starts:

2018-04-09 10:29:19,989 INFO [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:f0021131) Attempting to create storage pool be80af6a-7201-3410-8da4-9b3b58c4954f (RBD) in libvirt
2018-04-09 10:29:19,990 INFO [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:f0021131) Found existing defined storage pool be80af6a-7201-3410-8da4-9b3b58c4954f, using it.
2018-04-09 10:29:19,991 INFO [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:f0021131) Trying to fetch storage pool be80af6a-7201-3410-8da4-9b3b58c4954f from libvirt
2018-04-09 10:29:20,372 INFO [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:f0021131) Proccess agent ready command, agent id = 56

[yadvr]

I've marked this as blocker applicable for Ceph users, we'll try to get this fixed. @giorgiomassar8 can you advise any documentation on how to setup a small ceph storagepool to test this against KVM?

[wido]

Can you increase the logging to DEBUG on the Agent and show the XML which the Agent generates to define the storage pool?

The error you are seeing comes from libvirt+librados underneath so I'd need to see the XML it generates.

[giorgiomassar8]

I have set debugging on one of the agents and this is what I get:

2018-05-02 13:41:44,401 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-4:null) (logid:d06ebad5) Attempting to create storage pool be80af6a-7201-3410-8da4-9b3b58c4954f (RBD) in libvirt
2018-05-02 13:41:44,401 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:d06ebad5) Looking for libvirtd connection at: qemu:///system
2018-05-02 13:41:44,403 WARN  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-4:null) (logid:d06ebad5) Storage pool be80af6a-7201-3410-8da4-9b3b58c4954f was not found running in libvirt. Need to create it.
2018-05-02 13:41:44,403 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-4:null) (logid:d06ebad5) Didn't find an existing storage pool be80af6a-7201-3410-8da4-9b3b58c4954f by UUID, checking for pools with duplicate paths
2018-05-02 13:41:44,404 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-4:null) (logid:d06ebad5) Checking path of existing pool 9fb695bd-a47f-45d3-9fe7-f029dff431d8 against pool we want to create
2018-05-02 13:41:44,408 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-4:null) (logid:d06ebad5) Attempting to create storage pool be80af6a-7201-3410-8da4-9b3b58c4954f
2018-05-02 13:41:44,408 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-4:null) (logid:d06ebad5) <pool type='rbd'>
<name>be80af6a-7201-3410-8da4-9b3b58c4954f</name>
<uuid>be80af6a-7201-3410-8da4-9b3b58c4954f</uuid>
<source>
<host name='storagepool1' port='6789'/>
<name>cephstor1</name>
</source>
</pool>

2018-05-02 13:41:44,415 ERROR [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-4:null) (logid:d06ebad5) Failed to create RBD storage pool: org.libvirt.LibvirtException: failed to connect to the RADOS monitor on: storagepool1:6789,: Operation not supported
2018-05-02 13:41:44,415 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:d06ebad5) Seq 1-6775102689425489922:  { Ans: , MgmtId: 29010072043598, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.UnsupportedAnswer":{"result":false,"details":"Unsupported command issued: com.cloud.agent.api.ModifyStoragePoolCommand.  Are you sure you got the right type of server?","wait":0}}] }
2018-05-02 13:41:44,451 DEBUG [kvm.resource.LibvirtComputingResource] (Agent-Handler-4:null) (logid:d06ebad5) Execution is successful.
2018-05-02 13:41:44,453 DEBUG [cloud.agent.Agent] (Agent-Handler-4:null) (logid:d06ebad5) Watch Sent: Seq 1-6775102689425489921:  { Ans: , MgmtId: 29010072043598, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"details":"","wait":0}}] }
2018-05-02 13:41:44,464 DEBUG [utils.nio.NioConnection] (Agent-NioConnectionHandler-1:null) (logid:) Location 1: Socket Socket[addr=/10.20.0.21,port=8250,localport=45374] closed on read.  Probably -1 returned: Connection closed with -1 on reading size.
2018-05-02 13:41:44,464 DEBUG [utils.nio.NioConnection] (Agent-NioConnectionHandler-1:null) (logid:) Closing socket Socket[addr=/10.20.0.21,port=8250,localport=45374]
2018-05-02 13:41:44,464 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null) (logid:) Clearing watch list: 2
2018-05-02 13:41:46,728 INFO  [cloud.agent.Agent] (Agent-Handler-1:null) (logid:) Connected to the server
2018-05-02 13:41:49,465 INFO  [cloud.agent.Agent] (Agent-Handler-1:null) (logid:) Lost connection to the server. Dealing with the remaining commands...

In the generated XML there isn't the secret part, perhaps the agent is trying to use another authentication mechanism which this version of libvirt does not support?

This is what I have been using as a workaround, and it works:

<pool type="rbd">
  <name>be80af6a-7201-3410-8da4-9b3b58c4954f</name>
  <uuid>be80af6a-7201-3410-8da4-9b3b58c4954f</uuid>
  <source>
    <name>cephstor1</name>
    <host name='storagepool1' port='6789'/>
    <auth username='admin' type='ceph'>
      <secret uuid='OMITTED'/>
    </auth>
  </source>
</pool>

[wido]

Ok, I see. The operation not supported is odd, but it seems to be missing the cephx part indeed.

At the moment I do not have a 4.11 environment to test this with, but I'll look at the code later.

[nathanejohnson]

@wido The issue seems to be that for any KVM host, the disk format is always hard coded to QCOW2 here:

https://github.com/apache/cloudstack/blob/master/engine/orchestration/src/main/java/org/apache/cloudstack/engine/orchestration/VolumeOrchestrator.java#L768

This gets sent along to the agent. I guess this is a reasonable default for KVM, but obviously for RBD it needs to be RAW, and it won't know that until it looks up the storage pool. In the short term, I think hard coding the disk format to RAW on the agent side for RBD is valid, it can't be anything but that, but it might also be good for the management server to send along the correct disk type.

[nathanejohnson]

On second thought, this might be a separate bug we were chasing. We were getting seeing this error in the logs:

2018-05-03 09:58:03,932 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:fb29bd87) Attempting to create volume f2d800a0-fc19-4b41-b886-57
5af6742425 (RBD) in pool e485c675-896a-303e-be82-c42357c6b4c1 with size 5368709120
2018-05-03 09:58:03,932 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:fb29bd87) <volume>
<name>f2d800a0-fc19-4b41-b886-575af6742425</name>
<capacity>5368709120</capacity>
<target>
<format type='qcow2'/>
<permissions><mode>0744</mode></permissions></target>
</volume>

2018-05-03 09:58:03,932 DEBUG [kvm.storage.KVMStorageProcessor] (agentRequest-Handler-3:null) (logid:fb29bd87) Failed to create volume: 
com.cloud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtException: unsupported configuration: only RAW volumes are supported by this storage pool
at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.createPhysicalDiskByLibVirt(LibvirtStorageAdaptor.java:705)
at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.createPhysicalDisk(LibvirtStorageAdaptor.java:664)
at com.cloud.hypervisor.kvm.storage.LibvirtStoragePool.createPhysicalDisk(LibvirtStoragePool.java:115)
at com.cloud.hypervisor.kvm.storage.KVMStorageProcessor.createVolume(KVMStorageProcessor.java:1323)
at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.execute(StorageSubsystemCommandHandlerBase.java:119)
at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.handleStorageCommands(StorageSubsystemCommandHandlerBase.java:58)
at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtStorageSubSystemCommandWrapper.execute(LibvirtStorageSubSystemCommandWrapper.java:36)
at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtStorageSubSystemCommandWrapper.execute(LibvirtStorageSubSystemCommandWrapper.java:30)
at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtRequestWrapper.execute(LibvirtRequestWrapper.java:75)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1438)
at com.cloud.agent.Agent.processRequest(Agent.java:563)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:976)
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:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

@giorgiomassar8 were you seeing similar messages? We were receiving these messages on a freshly created pool when attempting to deploy a VM.

[wido]

@kiwiflyer Have you seen this one? The Agent is not providing the secret for the RBD storage pool to the libvirt XML definition.

[GabrielBrascher]

I will see if I can deploy a test environment to reproduce this issue meanwhile.

[giorgiomassar8]

@nathanejohnson nope I don't see qcow2/raw mismatch errors here, I do believe the issue is related to the fact that for some reasons, no authentication information is put in the pool's XML sent to libvirt.